vendredi 26 avril 2013

WANTED : Stacktraces

Lately, I ran into a situation on my production environment : I was getting NullPointerExceptions that did not have any stacktrace. In this article, I will describe what happened and analyse the cause of such a strange behaviour. This article is inspired by Andrey Vityuk's blog, where I found the first pieces of information I needed to fully understand the problem, so, thanks Andrey !

The problem

Until then, you were having a day just like every other one, getting rid of bugs in a production system, one by one. Everything else being done, you open that old ticket that mentions NullPointerException. Fine, usual business, seems not critical, and you think "let's just grab the production logs of yesterday !".

But then, you realise that all you have are lines like these :
2012-12-12 15:42:01 [main] ERROR Exception during feature xyz
java.lang.NullPointerException
2012-12-12 15:47:22 [main] ERROR Exception during feature xyz
java.lang.NullPointerException
2012-12-12 15:48:00 [main] ERROR Exception during feature xyz
java.lang.NullPointerException


The first thing you think is "Did the developper really write log.error("Error during feature xyz\n" + e.getClass()) ?". And also "How am I supposed to solve this bug without knowing where the NPE is thrown ?".

So you open the java file that contains the feature xyz and there, you see something that you did not expect :
log.error("Exception during feature xyz", e);


Your logging framework is correctly used, nothing to report here, but then why do you have no stacktrace ?

Guess what ? It's Hotspot's fault !

Fortunately, you find Andrey Vityuk's blog and discover that Hotspot can simply throw Exceptions that do not have stacktraces for performance sake.

Indeed, if Hotspot detects that you have a hot method that throws exceptions, it can decide to remove the stacktrace so that the exception throwing mechanism is faster. Some people might call this "a bug", I won't.

We should always remember that Hotspot job is to make our code run faster. Period.

When Hotspot optimises code, it rewrites that code, it merges methods, swaps instructions and compiles it to native code. Once this is done, you don't have anything that look like your Java classes. Unfortunately, this comes at a very high price when Exceptions starts to mess around since Hotspot has to do the exact opposite work to rebuild the consistent stacktrace that you are expecting.

By definition, Exceptions are exceptional (or at least, they should be). In some code bases, we can find exceptions that are used to implement business cases. This can for sure be considered as a code smell.

The code

Consider the following code :

public class StackTraceGenerator {
    public static void main(String[] args) {
        for (int i = 0; i < 16_000; i++) {
            System.err.print("iteration " + i + ", ");
            throwAndCatchNullPointerException();
        }
    }

    private static void throwAndCatchNullPointerException() {
        try {
            throwNPE();
        } catch (NullPointerException e) {
            System.err.print(e.hashCode() + ", ");
            e.printStackTrace();
        }
    }

    private static int throwNPE() {
        return ((Object) null).hashCode();
    }
}


If you run this code with C2 (-server), you may eventually see that it generates exceptions without stacktraces. On my machine, it happens around iteration 10,050.

$ java -server fr.pingtimeout.StackTraceGenerator
iteration 0, 1442002549, java.lang.NullPointerException
        at fr.pingtimeout.StackTraceGenerator.throwNPE(StackTraceGenerator.java:27)
        at fr.pingtimeout.StackTraceGenerator.throwAndCatchNullPointerException(StackTraceGenerator.java:19)
        at fr.pingtimeout.StackTraceGenerator.main(StackTraceGenerator.java:13)
[...]
iteration 10015, 533361599, java.lang.NullPointerException
        at fr.pingtimeout.StackTraceGenerator.throwNPE(StackTraceGenerator.java:27)
        at fr.pingtimeout.StackTraceGenerator.throwAndCatchNullPointerException(StackTraceGenerator.java:19)
        at fr.pingtimeout.StackTraceGenerator.main(StackTraceGenerator.java:13)
iteration 10016, 27836516, java.lang.NullPointerException
iteration 10017, 27836516, java.lang.NullPointerException
[...]


Exceptions without Stacktraces, behind the scenes

In the print statement, I included the hashCode of the exception that was thrown. This is completely intended since it shows that after the optimisation is applied, the same exception is thrown for each call to throwNPE.

Indeed, the way Hotspot optimises this code is the following :
  • Create an instance of the exception that should be thrown
  • Clear its stacktrace
  • Cache this exception
  • Throw this exception instead of creating a new one for future calls


So hotspot does not only truncate stacktrace but also optimises the instance creation. At first, I thought that it was an optimisation in the way try/catch blocks work under heavy pressure, but it is not the case. Simply put, this optimisation consists in a singleton for a given exception, the rest of the code stays identical. Main gain : Hotspot does not have to rebuild a new stacktrace from optimised code each time the exception is thrown.

This behaviour is triggered by the JVM flag OmitStackTraceInFastThrow which is activated by default. We could get rid of it using -XX:-OmitStackTraceInFastThrow but I would not do that.

Final thoughts

This exception was the result of a coding mistake and happened enough time so that hotspot optimised it. It should be easily reproducible on any machine and be fixed right away.

We should not reduce the performance of a whole system in order for a bug to be easily fixed.

Ever faced this situation ? Another war story to share ? Let's discuss it in the comments !

vendredi 12 avril 2013

Extracting iCMS data from garbage collector logs

Recently, I had to inspect some GC logs that had been created on a recent Hotspot JVM, using ParNew, CMS and iCMS. I did not find any tool that could report any information on iCMS duty cycles, so I wrote one that allows me to spot iCMS problem in a matter of seconds.

The problem

The Concurrent Mark and Sweep GC is almost always used on websites that have a lot of traffic and that cannot tolerate long pauses. Its incremental mode is often used on servers with limited hardware, so that small CMS collections on small chuncks of memory are executed between minor collections.

However, I could not find any GC log parser that took advantage of iCMS duty cycles information. In particular, how can we instantly see that something is wrong with our GC tuning ?

Incremental CMS reports

iCMS reports can be seen in ParNew GC log, in "icms_dc=..." parts of the message. For instance, take the following message :

18.862: [GC 18.862: [ParNew: 136320K->15040K(153344K), 0.0167820 secs] 158326K->37046K(2080128K), 0.0168440 secs] [Times: user=0.10 sys=0.00, real=0.02 secs]
21.028: [GC 21.028: [ParNew: 151360K->15263K(153344K), 0.0458710 secs] 173366K->48678K(2080128K) icms_dc=5 , 0.0459650 secs] [Times: user=0.22 sys=0.00, real=0.05 secs]


This log shows us that two minor collections that occurred at 18.862ms and 21.028ms and an information about a iCMS collection. This collection was ran between the two ParNew collections and took 5% of the time between them. So, let's do some math.

21.028 - 18.862 = 2.166 secs
5% of 2.166 secs = 0.1083 secs


=> The iCMS collection took 108.3ms to complete, in the time frame of 2.166 seconds between the two ParNew Collections. This collection took place concurrently, so our application only suffered of a small overhead.

Some bad values

These log message were describing a normal situation, however, what would you think about these?

928404.003: [GC 928404.003: [ParNew: 140485K->17024K(153344K), 0.0724360 secs] 1854871K->1745355K(2080128K) icms_dc=100 , 0.0726830 secs] [Times: user=0.33 sys=0.00, real=0.07 secs]
928405.145: [GC 928405.145: [ParNew: 153344K->13475K(153344K), 0.0365750 secs] 1786382K->1660879K(2080128K) icms_dc=100 , 0.0368000 secs] [Times: user=0.18 sys=0.01, real=0.04 secs]


Yes, you read well, iCMS duty cycles ran 100% of the time between ParNew collections.

With ParNew being a stop-the-world collector, we can conclude that at 928404.003, a ParNew collection stopped the application for 0.07 seconds, afterwhat a incremental CMS collection was run concurrently during the whole time the application was working, and until it was stopped again at 928405.145 by a new ParNew collection.

So basically, during that time frame, our application was either paused or slowed by an iCMS collection.

Now, the big question is, if we have a 3-days GC log, how can we instantly know that we have a problem linked to iCMS duty cycles ?

Cumulative frequency of iCMS

My idea was to create a graph that sums the ratio of icms_dc time during the execution of the application.

The graph has the following characteristics :
  • X axis is the time spend in iCMS duty cycle in percent
  • Y axis is the cumulative frequency of such iCMS duty cycles


My goal is to have the lowest possible iCMS duty cycles, so let's say that I want 90% of my iCMS collections taking less than 10% of the time between two minor collections.

With such requirements, I can say that this GC log has no problem regarding iCMS :



However, this application does. It suffers from long iCMS duty cycles and some measures should be taken to reduce the pressure of Garbage Collectors. We can see that only 80% of iCMS cycles take less than 20% of the time available, which is not good. Even worse, look at the 90th, 95th and 99th percentiles. iCMS is definitely working too much and causes too much overhead on the application.



Finally, I can merge my graphs to make sure that my tuning is really improving the application Garbage Collections.



Conclusion

The scripts I created to generate those charts are available on GitHub under the GPL licence. You can find them here : https://github.com/pingtimeout/icms-cumulative-frequency. I hope it will be useful :-)

Do you have other diagnostic techniques ? Some ideas to share ? Let's talk about it in the comments !

lundi 1 avril 2013

Retour sur Devoxx France - BOF NoSSII

La semaine dernière, je me suis rendu au BOF NoSSII de Devoxx France 2013. Une no-conférence très intéressante où l'on ne parlait pas de langage, de framework ou d'outils. Réactions.

Les sociétés présentes, la notion de valeurs

Dans le panel d'animation du BOF, trois sociétés étaient représentées : Lateral Thoughts, Ninja Squad et Scopyleft.

Leurs dirigeants-employés-salariés-geeks ont pu nous présenter les raisons qui les ont amenés à se regrouper, ainsi que celles qui les ont poussé vers tel ou tel statut juridique.

Le point qui m'a le plus marqué est celui des valeurs. Chaque société s'est créée sur une définition des valeurs qui vont l'animer durant toute son existence. L'objectif principal de ces entreprises est de fédérer des développeurs vers un but commun, or ce but ne peut pas être la rentabilité financière puisque, soyons francs, à un moment où à un autre, une meilleure situation se présentera toujours (par exemple, Google vous débauche pour aller bosser à SF et vous propose un salaire à 6 chiffres).

Ce qui unit ces entreprises, ce sont leurs valeurs. Parce que c'est la seule chose qui maintiendra la cohésion d'une équipe quand les temps seront difficiles.

NoSSII = Not Only SSII

Une bonne partie des échanges (la première demi-heure) a beaucoup tourné autour de la définition d'une SSII. Plusieurs définitions s'opposent.

La SSII est une entité qui travaille par engagement de résultat (projets au forfaits) ou par engagement de moyens (projets en régie, prestations client). L'industrie du logiciel est similaire à toutes les autres, dans la mesure où l'on se demande toujours s'il faut faire (réaliser un soft en interne avec ses propres employés) ou faire-faire (externaliser le développement, faire appel à des prestataires). De ces deux points, on peut conclure que les indépendants sont tous des SSII mono-personnelles. Les trois sociétés présentes sont également des SSII, au même titre que les habituels Steria, Capgemini & co.

Mais ce n'est pas la seule définition valable.

Une SSII, c'est une société qui place des ressources sur des projets (forfait ou régie) et dont la ligne directrice est définie par un patron pour être ensuite relayée par toutes les hiérarchies du groupe. C'est ce que je retiens de mon expérience chez Steria, c'est également ce qui a été partagé par le public. Une SSII ne cherche pas à aller plus loin que le placement de collaborateurs. La prestation est la finalité.

Chez Lateral Thoughts, Ninja Squad et Scopyleft, en revanche, la prestation est un moyen. Un moyen pour arriver, par exemple, à créer un logiciel et à en vivre. Cette nouvelle finalité est décidée par l'ensemble des co-gérants, de façon collégiale. En ce sens, ces entreprises ne sont pas des SSII.

Alors en sont-elles ? N'en sont-elles pas ? En sont-elle un peu mais pas totalement ? C'est justement là que se trouve l'essence du terme NoSSII : oui, elles sont des SSII, mais pas complètement (Not Only).

Ok, mais est-ce que ça marche ? Et est-ce que ça scale ?

LT, NS et Scopyleft sont encore relativement jeunes (respectivement 1 an et demi, 1 an, 3 mois) mais le modèle a l'air pérenne. Elles sont de petite taille (entre 3 et 8 personnes) et donc on peut se demander si elles pourront croître sans perdre leurs valeurs.

EDIT : Comme le dit Scopyleft
sur twitter, la croissance n'est pas nécessairement l'objectif de toute société.

Il y a relativement peu d'exemples de sociétés participatives qui fonctionnent sur ce modèle et qui ont un grand nombre d'associés. Je n'ai pas noté le nom de celle qui était cité en exemple, mais il s'agissait d'une Scop de plusieurs centaines de salariés. D'après Wikipedia, la taille moyenne d'une Scop est de 21 salariés, ce qui laisse une belle marge de progression :-)

Une question de risque

Ce que je retiens surtout de cette conférence est lié au risque que tu prends.

Lorsque tu es salarié d'une SSII traditionnelle, le risque que tu prends est très faible car tu as un CDI, un salaire garanti, une mutuelle, tout ça sans te soucier de quoi que ce soit. Bref tu es au chaud. Le salaire en revanche peut être un peu décevant quand tu vois les prix pratiqués par la profession.

Si en revanche tu es indépendant, le risque est plus grand, car d'un mois à l'autre tu peux voir ta prestation ne pas être renouvelée. Ce risque est quand même limité à ta seule personne : si tu te plantes, tu te plantes seul et tu peux toujours revenir dans des SSII traditionnelles. Côté salaire, il est plus élevé.

Maintenant, si tu fais partie d'une société participative, les décisions que tu prends, en tant que co-gérant, vont impacter la vie de tes associés. Ce risque est donc aussi grand qu'en étant indépendant, mais avec un impact sur d'autres personnes. De qui donner des sueurs froides.

Une grande responsabilité

Lorsque tu es en SSII classique, la vie de ta société ne t'intéresse pas puisque tu n'as aucun moyen pour peser dans les décisions. Tu te laisses porter, on verra bien où ça te mène.

En tant qu'indépendant ou en société participative, tu *décides*, et ça c'est un grand changement. Tu es acteur dans la vie de ton entreprise, tu ne peux pas simplement te laisser porter, tu portes la responsabilité te tes décisions, tu es maître de ton outil de travail et tu choisis ce que tu veux en faire.

Ça peut faire peur, car cela demande du courage et de la force. S'engager dans une société participative en demande autant que lorsque tu veux passer indépendant. Être en NoSSII, c'est être indépendant, mais en équipe. Une belle leçon de courage qui donne à réfléchir.