Curieux comportements de log4j par Dominique0796 - page 1

Salut,
voilà, en faisant des tests pour évaluer la vitesse de log4j, j'ai remarqué quelque chose d'intéressant :

Essayez ce code :

import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;

public class exemple4
{
  static Logger log = Logger.getLogger("org.progx");

  public exemple4()
  {
    log.info("Application is alive.");
  }

  public static void main(String[] args)
  {
	

    PropertyConfigurator.configure("exemple4.properties");
    long start = System.currentTimeMillis();
   int h = 0;
    log.warn("Starting application");
          
    System.out.println("Accompli en "+(System.currentTimeMillis()-start)+" milli-secondes.");
  }
}

Bon, testez ce code, eh bien le résultat est 0 milli-secondes, sauf si on lance le code plusieurs fois de suites sans lui laisser le temps de se retrouver ... et là, c'est 16 sec.

bon, passons à la constatation suivante:

Testez ce code :

public static void main(String[] args)
  {
	

    PropertyConfigurator.configure("exemple4.properties");
    long start = System.currentTimeMillis();
   int h = 0;
    log.warn("Starting application");
    log.warn("Closing prog"); 
    System.out.println("Accompli en "+(System.currentTimeMillis()-start)+" milli-secondes.");
  }

Ici, le résultats est quasiment toujours 16, sauf une fois sur 10 environ où c'est 0.

Bon, maintenant, essayez ça :

<lien url="null">

public static void main(String[] args)
  {
	

    PropertyConfigurator.configure("exemple4.properties");
    long start = System.currentTimeMillis();
   int h = 0;
    log.warn("Starting application");
      h++;
      h=h;
      h++;
    log.warn("Starting application");
    System.out.println("Accompli en "+(System.currentTimeMillis()-start)+" milli-secondes.");
  }

He bien là, on a 15, 16 ou 0 milli-secondes, mais, le plus souvent c'est 0 sec ...
Vous ne trouvez pas que c'est bizarre ?
Déjà, une écriture de log = 0 , et deux logs = 16 sec ... c'est bizarre non ?
De plus, quand on insère un peu de code entre les deux écriture, il y a plus de chance que ça prenne 0 sec au lieu de 16 ...

J'ai pensé au Thread ...
l'écriture ce passe dans un autre thread, mais si une autre demande d'écriture arrive avant que l'autre soit écrite, log4j met le thread principal en pause jusqu'à ce qu'il est fini le traitement ...
c'est une hypothèse ...

qu'en pensez-vous ?

Un autre constat :

le résultat donné par 4 écriture de log à la suite :

configurationOptionStr=null
0 WARN [main] org.progx null - Starting application
0 WARN [main] org.progx null - Starting application
16 WARN [main] org.progx null - Starting application
16 WARN [main] org.progx null - Starting application
Accompli en 16 milli-secondes.

Je suppose que le chiffre précédent la phrase est le temps ...
On voit que les deux dernier on pris chacun 16 secondes, et le temps total est 16 sec, ce qui appuie mon hypothèse des threads.

Et la grosse différence de temps serait dû au fait que le fichier des logs ne peux pas être modifier plusieurs fois en même temps ...

Dominique0796

27 mai 2011 à 13:39:52

Sim the Boss

27 mai 2011 à 14:43:37

Tout dépend de la charge de ton processeur à l'instant t de l'exécution.
J'ai pas compris le problème : en quoi c'est gênant que le temps d'exécution oscille entre 0 et 16 ms ?

Maximus48

27 mai 2011 à 14:51:39

Je pense que le plus génant c'est qu'il a compris 16 secondes

27 mai 2011 à 14:56:57

Citation : Maximus48

ouais enfin, vous avez compris, c'est l'essentiel ! :-°

Citation : Sim the Boss

C'est pas gênant, seulement, si ce que je dit est juste, c'est plus rentable d'espacer les écriture que de les mettre à la suite ... ça peu être intéressant quoi ...

Pour la charge du processeur, c'est vrai, c'est tout à fait plausible ...

Curieux comportements de log4j

Curieux comportements de log4j

Supprimer

Modérer

Signaler le message aux modérateurs