Je veux mesurer les statistiques de performance pour certaines tâches de Spring, consistant en plusieurs appels de méthode chacun. Ces statistiques de performances ne doivent pas inclure les temps nécessaires pour les requêtes de base de données. Par conséquent, j'intercepte les méthodes DAO en utilisant un aspect Spring AOP dans lequel j'arrête la mesure de la tâche et démarre une mesure séparée pour l'appel de la base de données. Les deux mesures fonctionnent, le problème est, que le CPU & temps de l'utilisateur obtenu par ThreadMXBean n'augmente pas parfois pendant l'une des différentes sections mesurées. En tant que ces sections, je veux dire A) la mesure de la tâche avant un appel DB, B) la mesure de l'appel DB et C) la mesure de la tâche après l'appel DB. J'ai obtenu des mesures raisonnables pour chaque section mais pas pour les trois en même temps. Il semble qu'au moins l'un d'entre eux (au hasard comme il semble) ne montre aucun accroissement dans le CPU & Temps de l'utilisateur.Différence de temps processeur et utilisateur mesurée au hasard de 0 avec ThreadMXBean au printemps avec AOP
Dans ce qui suit est un code d'exemple visualiser mon cas de problème:
@Api
@Path("task1")
@Consumes(MediaType.APPLICATION_JSON)
@Produces(MediaType.APPLICATION_JSON)
public class task1Resource {
@Autowired
private MeasurementService measurementService;
@POST
public Response startTask(...){
measurementService.start("task1", false);
//Transactional service methods with the business logic for task1
//are called
measurementService.end("task1");
return Response.ok(entity).build();
}
}
@Service
@Transactional
public class MeasurementService {
@Autowired
private MeasurementDAO measurementDao
public void start(String task, boolean interrupted){
MeasurementObject measurementObj = new MeasurementObject();
ThreadMXBean mxBean = ManagementFactory.getThreadMXBean();
if(interrupted){
//Get the previously persisted measurement object for the task
measurementObj = measurementDao.get(task);
//Calculate the differences with the values of the previous section
measurementObj.calcCpuTimeDifference(mxBean.getCurrentThreadCpuTime();
measurementObj.calcUserTimeDifference(mxBean.getCurrentThreadCpuTime();
}else{
//Initialize
measurementObj.setTask(task);
Set<DAOMeasurement> daoCalls = new HashSet<DAOMeasurement>();
measurementObj.setDaoCalls(daoCalls);
Thread currentThread = Thread.currentThread();
measurementObj.setThread(currentThread);
measurementObj.setCpuTime(mxBean.getCurrentThreadCpuTime);
measurementObj.setUserTime(mxBean.getCurrenThreadUserTime);
}
measurementDao.save(measurementObj);
}
public MeasurementObject end(String task){
//Get the measurement object for the task
MeasurementObject measurementObj = measurementDao.get(task);
ThreadMXBean mxBean = ManagementFactory.getThreadMXBean();
//Calculate the differences with the values from the start
//or the previously calculated differences
measurementObj.calcCpuTimeDifference(mxBean.getCurrentThreadCpuTime());
measurementObj.calcUserTimeDifference(mxBean.getCurrentThreadUserTime());
return measurementDao.save(measurementObj);
}
}
@Aspect
@Component
public class daoAspect {
@Autowired
private MeasurementService measurementService;
@Autowired
private DAOMeasurementService daoMeasurementService;
@Before("daoMethods() && !measurementMethods()")
private void start(Joinpoint jopo){
Thread currentThread = Thread.currentThread();
//Get the task measurement object that was started in the same thread
MeasurementObject measurementObj = measurementService.byThread(currentThread);
measurementObj = measurementService.end(measurementObj.getTask());
//Start the measurement for the DB call
DAOMeasurementObject daoMeasurementObj = daoMeasurementService.start(measurementObj);
}
@After("daoMethods() && !measurementMethods()")
private void end(Joinpoint jopo){
Thread currentThread = Thread.currentThread();
/*Please assume here that we only have one dao method
* (In my more complex case I query the database for
* the correct daoMeasurementObject by using additional parameters)
* So here we find the DB call measurement object that was started
* in this thread and end it. */
DAOMeasurementObject daoMeasurementObj = daoMeasurementService.byThread(currentThread);
daoMeasurementService.end(daoMeasurementObj);
//We get the task measurement object for this thread and start it again
MeasurementObject measurementObj = measurementService.byThread(currentThread);
measurementService.start(measurementObj.getTask(),true);
}
@Pointcut("execution(* com.foo.bar.dao.*(..))")
public void daoMethods(){}
@Pointcut("@annotation(Measurement)")
public void measurementMethods(){} //I annotated the measurement dao classes with this annotation
}
@Service
@Transactional
public class DAOMeasurementService {
/*This class is identical to the MeasurementService class with the
* difference that a DAOMeasurementObject gets a MeasurementObject
* reference. But the cpu-&user-times are calculated in the same manner */
}
Comme je l'ai dit la configuration générale fonctionne. La mesure de tâche commence et se termine comme elle est supposée l'être et la méthode DAO entre les deux est interrompue par l'aspect. De plus, la mesure semble fonctionner correctement car j'ai parfois des valeurs correctes. Le seul problème est que parfois l'utilisateur fois CPU- & ne changent pas depuis le début d'un ou deux des trois mesures sections à la fin d'entre eux qui se traduit par des valeurs de différence calculées de 0.
De plus, je vérifié que toutes ces méthodes ont le même Thread.currentThread() et ThreadMXBean.isCurrentThreadCpuTimeSupported() et ThreadMXBean.isThreadCpuTimeEnabled() retour vrai sur tous les points de mesure.
Je serais vraiment heureux pour de l'aide ou des conseils! Et si vous avez besoin de plus de code ou d'informations, n'hésitez pas à le demander.
Mise à jour:
J'ai testé le système avec un aspect @Around au lieu des @Before et @After aspects et avec de multiples pistes. Le résultat est toujours le même. Les valeurs ThreadMXBean.getCurrentThreadCpuTime et ThreadMXBean.getCurrentThreadUserTime n'augmentent pas aléatoirement pendant une à deux des phases de mesure, mais augmentent au contraire entre elles. Par exemple: Phase A) la mesure au début de la tâche montre un temps CPU de 280801800 et un temps utilisateur de 265201700 et lorsque cette mesure est arrêtée pendant l'interception DAO, elle affiche à nouveau un temps CPU de 280801800 et un utilisateur -temps de 265201700. Puis au début de la phase B), la mesure de la méthode DAO, il montre un temps CPU de 296401900 et un temps utilisateur de 280801800. Mais à la fin de la mesure de la méthode DAO, il montre encore la même temps CPU de 296401900 et le même temps utilisateur de 280801800. Pendant la phase complète C) les temps restent les mêmes qu'en B).
-> Est-il possible que le ThreadMXBean ne met à jour ses statistiques qu'à certains intervalles et non quand ses méthodes sont appelées? Les phases que j'essaie de mesurer à ce moment sont relativement courtes, elles ont une durée de 1 à 10 millisecondes (en utilisant LocalDateTime).