InetAddress.isReachable() jest do bani

Napisałem mały program testujący czy klient "widzi" prawidłowo adres i porty naszego serwera aplikacyjnego. Zdarza się, że Firewalle klientów skutecznie blokują łączność.

Zależało mi, aby w pierwszym kroku "spingować" hosta. Niestety wczoraj odkryliśmy buga, bo polegałem na metodzie InetAddress.isReachable(). Tymczasem sposób jest do chrzanu, bo implementacja nie pinguje a odpytuje usługę echo, która stoi na porcie 7. Wielu adminów blokuje tego typu usługi, starając się maksymalnie uszczelnić serwery. U nas w firmie też i dlatego nasi klienci dostawali informację, że istnieje brak łączności z jednym z serwerów.

Nie dostarczę dzisiaj rozwiązania, z braku czasu, ale wrócę do tematu kiedyś.
Poniżej wadliwy kod:

[sourcecode type="java"]

final String host = "zdanek.ostrejezyki.pl";
final int timeOut = 3000;

final boolean status = InetAddress.getByName(host).isReachable(timeOut);

if (status == false) {
throw new IOException("Brak lacznosci z " + host);
}

[/sourcecode]

Zero Cobertura coverage

Recently I had zero code coverage during tests. I had a maven2 project (under maven 1.0.9), with default cobertura version, which was 1.9.

All reports were generated normally except all code coverage was zero (0).



The reason was somehow buggy cobertura version 1.9.
After I put cobertura-maven-plugin configuration into my pom.xml specifying cobertura version 2.4

[sourcecode language="xml"]

<plugin>
<groupId>org.codehaus.mojo</groupId>
<artifactId>cobertura-maven-plugin</artifactId>
<version>2.4</version>
</plugin>

[/sourcecode]

all went well and finally I had my non-zero coverage :D



(Edit: I've added some pretty screenshots :])

W końcu logować z IF (isDebugEnabled()) czy nie?!

Ostatnio staram się pisać małe metody, w imię czytelności kodu. W związku z tym każda dodatkowa linijka zwiększa objętość metody. W malutkich metodach jedna linia to nawet kilkadziesiąt procent objętości :) A co z logowaniem informacji debugujących? Zgodnie z zaleceniami autora Log4j (bo tego loggera zazwyczaj używam), przed zalogowaniem debug() powinno się sprawdzić czy ten poziom jest włączony, aby niepotrzebnie nie tracić czasu procesora na inicjalizowanie stringa do zalogowania. Ceki Gülcü, autor Log4j, w 2002 przekonywał, że sprawdzanie IFem poziomu na PII 233MHz zajmuje nanosekundy, co stanowi mały narzut. Rzeczywiście. A co, gdyby w imię czytelności kodu zrezygnować z tego sprawdzania? Co się wówczas stanie? Ile czasu stracimy? I czy mimo wyłączonego logowania niepotrzebnie wiadomość będzie przetwarzana wewnątrz loggera?

Otóż, oba popularne loggery Log4j i java.utils.Logging sprawdzają czy dany poziom jest włączony i oczywiście nie logują komunikatu, jeśli nie pasuje do poziomu. W takim razie jedynym istotnym problemem jest czas konstruowania wiadomości do zalogowania. Zazwyczaj jest to operacja sklejania kilku stringów, bo chcemy zalogować jakąś operacje np. z jej parametrami. Warto przy tym zauważyć, że czasy kiedy "jakiś string" + "inny" powodowało kilka wywołań konstruktora String(). Od javy 1.5 (lub wcześniej, bo nie wiem) , sklejanie stringów zawsze jest zastępowane StringBuilderem, a więc jest bardzo efektywne. W związku z tym, każdorazowo należy rozważyć czy dany string, który chcemy zalogować jest złożony czy nie. Jeśli nie, to moim zdaniem nie warto stosować IFów, tylko bezwzględnie pchać go loggera.

A teraz konkretne miary, jako, że jestem inżynierem. Test wykonany na procku dual core 2.66GHz, czyli rząd wielkości szybszy od twórcy Log4j. Dzisiaj uważany za przeciętnie dobry sprzęt.
Napisałem program, który 100 000 razy loguje wiadomość, przy wyłączonym debugowaniu. Przy czym w pierwszym teście odbija się od sprawdzenia IFem czy włączone jest debugowanie, a w drugim wchodzi do środka metody logującej. Logowany string to

"Wiadomosc testowa, index " + i + " i jeszcze string"

Mamy tu 3 operacjie StringBuilder.add(), przy czym dla int i jest najbardziej kosztowna, bo i jest od razu zamieniane na string. Wynik:

Test logow bez wlaczonego debuga, ze sprawdzaniem IF
Czas 0ms
Test logow bez wlaczonego debuga, bez sprawdzania IF
Czas 93ms

0 ms oznacza rzeczywiście submilisekundowe czasy sprawdzania czy poziom to DEBUG. 93 ms w rozłożeniu na 100 tyś. wywołań daje nam 93 ns (nano sekund!) na sklejanie. Dodam na koniec, że zaskoczony wynikiem podejrzewałem mocną optymalizację ze strony JVM, czego nie da się wykluczyć, ale drugi test z wielokrotnym powtórzeniem logowanej wiadomości (czyli rezygnacja z pętli) dało również submilisekundowe wyniki. Wkleiłem setkę razy

logger.debug("Wiadomosc testowa, index " + (i++) + " i jeszcze string");

Konkluzja: moim zdaniem przy prostej treści logowanej wiadomości, można zrezygnować ze sprawdzania poziomu logowania na rzecz uproszczenia (wizualnego) kodu.

Źródełko:

[sourcecode language="java"]
package pl.ostrejezyki.zdanek;

import org.apache.log4j.ConsoleAppender;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;

public class LoggingEffectivenessTests {

private static Logger logger = Logger.getLogger(LoggingEffectivenessTests.class);

public static void main(String[] args) {

initLog4j();

testCheckingIfDebugIsEnabled();
testWithoutCheckingIfDebugIsEnabled();

}

private static void testWithoutCheckingIfDebugIsEnabled() {
long start;
long stop;
System.out.println("Test logow bez wlaczonego debuga, bez sprawdzania IF");

start = System.currentTimeMillis();
for (int i = 0; i &lt; 100000; i++) {
logger.debug("Wiadomosc testowa, index " + i + " i jeszcze string");
}
stop = System.currentTimeMillis();

System.out.println("Czas " + (stop - start) + "ms");
}

private static void testCheckingIfDebugIsEnabled() {
System.out.println("Test logow bez wlaczonego debuga, ze sprawdzaniem IF");

long start = System.currentTimeMillis();
for (int i = 0; i &lt; 100000; i++) {
if (logger.isDebugEnabled()) {
throw new IllegalStateException("Debug wlaczony, a powinien byc wylaczony");
}
}
long stop = System.currentTimeMillis();

System.out.println("Czas " + (stop - start) + "ms");
}

private static void initLog4j() {
Logger l = Logger.getRootLogger();
ConsoleAppender ca = new ConsoleAppender();
l.addAppender(ca);
l.setLevel(Level.ERROR);
}
}
[/sourcecode]

Consumer Driven Contracts - prezentacja Adama Lidera na WJUG

Wczoraj na WJUGu wystąpił Adam Lider z demonstracją Consumer Driven Contracts. Opisywał duży, rozproszony system i problemy związane z jego wdrożeniem i utrzymaniem. Była to bardzo ciekawa prezentacja, ponieważ oprócz tego, że Adam był bardzo dobrze przygotowany i naturalny, to opowiadał o własnych doświadczeniach, bo przy projekcie pracował kilka lat.

Była również dodatkowa atrakcja, bo z powodu Świąt było zamknięte "akwarium" i nie mieliśmy rzutnika multimedialnego (Michale!) i dlatego musieliśmy się ścisnąć wokół laptopa Adama. To było integrujące! :)

[caption id="attachment_114" align="aligncenter" width="480" caption="Adam Lider prezentuje CDC, bez projektora"][/caption]