0

I have a logging bean where I log how long database calls and bean method calls take via interceptors.

I have a bean that calls two @Asynchronous methods. Those two @Asynchronous methods call the database and are intercepted.

When the logging bean logs though, it appears that the database has taken 0 ms which can't be right. When I use this logging bean and all the interceptors without @Asynchronous calls everything works fine.

I'm using glassfish 3.1.2.2. The doc http://glassfish.java.net/nonav/docs/v3/api/javax/enterprise/context/RequestScoped.html says "The request context is destroyed: after the asynchronous observer notification completes," Does that mean that my logging bean instance in the @Asynchronous method is destroyed when the method completes? What can I use to accomplish my goal?

user1608137
  • 33
  • 5

1 Answers1

0

There are multiple layers:

  1. A CDI proxy, which runs CDI interceptors and then calls the EJB.
  2. An EJB proxy, which schedules async work and returns immediately.
  3. EJB interceptors, which run on the async thread.

Presumably, you're using a CDI interceptor, which is measuring the time it takes for the EJB container to schedule the async work. If you switch to using an EJB interceptor instead (i.e., annotate the EJB method with @Interceptors), then you can measure the time taken to execute the work.

Brett Kail
  • 33,593
  • 2
  • 85
  • 90
  • I think i'm using EJB interceptors. I have @Interceptors({Class.class} annotated at the class level and the imports look like this import javax.interceptor.AroundInvoke; import javax.interceptor.InvocationContext; – user1608137 Mar 18 '13 at 15:41
  • I was sure this was in the EJB spec, but I can't find it now. Perhaps there is a discrepancy amongst implementations. I tested on WebSphere Application Server, and it invokes interceptors on the async thread. Perhaps try printing Thread.currentThread().toString/.getId/.getName from the interceptor and the async method to confirm the Glassfish behavior? – Brett Kail Mar 18 '13 at 16:46
  • The interceptors are getting executed correctly for the Async methods. They call the LoggingBean after invocation.proceed() and add the time it took to talk to the database to the loggingbean... e.g. invocation.proceed(); loggingbean.addDBTime(System.currentMillis() - start); all that works correctly, but when the final interceptor (at the jersey level) calls the loggingbean.log() method, the dbtime is 0. i've checked that the db interceptor logs a non 0 time – user1608137 Mar 18 '13 at 20:51
  • What value is being passed to addDBTime? What is logginbean? How was it created/obtained? Are the addDBTime and log methods being called on the same loggingbean instance? – Brett Kail Mar 18 '13 at 22:56
  • i pass longs (primitive) to the addDBTime method. loggingbean is a requestscoped class that has methods addDbTime(long l), setURI(String s), setJerseyTime(long l) and setEJBTime(long l). loggingbean is @Injected into the interceptors that capture how long each process took. I don't know if addDBTime and log are being called on the same instance. Should i just println(LoggingBean) to see the place in memory? – user1608137 Mar 18 '13 at 23:37
  • Assign each logging bean an identity (e.g., static AtomicInteger), and add logging to each of the methods. I would guess that the request scope is "lost" when switching threads for the async call. – Brett Kail Mar 19 '13 at 16:12