Better test logs in parallel maven builds

Running Apache Maven in parallel

Apache Maven has a nice way to speed up builds by leveraging multiple CPU cores to build different modules in parallel.

$> mvn clean install -T8

will take 8 cores for your build.

More on parallel builds can be found here https://cwiki.apache.org/confluence/display/MAVEN/Parallel+builds+in+Maven+3

Failure analysis in Jenkins

But did you ever try to use parallel builds on a huge project when running in Jenkins (or locally with | tee some.log) and something did break?

You will end up with a big mess in your log file because all the output from multiple threads end up interweaved with each other. And you have no clue to detect which log line comes from which thread – and thus you also have no clue which log line comes from which module. Doesn’t exactly make finding failures easy.

How to separate the log lines?

What I did in many of my business project to get rid of this problem is the following little hack (I’m using testng, but it’s similar in JUnit):

@BeforeMethod(alwaysRun=true)
public final void markThreads() {
  Thread.currentThread.setName(
      Thread.currentThread.getId() + " - " + 
      this.getClass().getSimpleName());
}

You can provide this in a base class for all your unit tests for example.
You will now get the name of the test class for each log line since the thread name gets printed out be default in all log frameworks I know.

PS: with one could also switch surefire to generate a single file per test. But that slows down the build a bit and you end up with 2500 files. And it’s rather hard to catch side effects you got from previous tests leaving over state (SHOULD not be, but such bugs happen).

toString(), equals() and hashCode() in JPA entities

Many users have generated toString, equals() and hashCode() methods in their JPA entities.
But most times they underestimate what impact that can have.

This blog post post is inspired by a chat I had with Gavin King and Vlad Mihalcea.

Preface: I like to emphase that I take a big focus on keeping the customer code portable across different JPA vendors. Some ‘Uber trick’ might work in one JPA vendor and totally mess up the others. Each JPA provider is broken in it’s own very special way. Trust me, I know what I am talking about from both a user and a vendor perspective… The stuff I show here is the least common denominator for JBoss Hibernate, EclipseLink and Apache OpenJPA. Please shout out if you think some of the shown code does not work on one of those JPA containers.

toString()

What’s wrong with most toString() methods in entities?
Well, most of the times developers just use the ‘generated toString’ shortcut to create this method. And that means that the generated toString() method usually just reads all the attributes of your entity and prints it.

What happens if you touch an attribute really depends in a high degree which ‘mode’ your JPA provider runs in. In Hibernate you often have the pure class. In that case not much will happen if you only read the attributes which are not Collections etc. By ‘using attributes’ I mean this.fieldname and not using getters like this.getFieldname(). Simply because Hibernate does not support lazy loading for any other fields in that mode. However, if you touch a @OneToMany or an @ElementCollection field then you will force lazy loading on the first time toString() gets invoked. It might also behave different if you use the getters instead of reading the attributes.

And if you use EclipseLink, Apache OpenJPA or even Hibernate in byte-code weaving mode or if you get a javassist proxy from Hibernate(e.g from em.getReference()) then you are in even deeper troubles. Because in that case touching the attributes might trigger lazy loading for any other field as well.

I tried to explain how the enhancement or ‘weaving’ works in JPA in a blog post many years ago https://struberg.wordpress.com/2012/01/08/jpa-enhancement-done-right/ Parts of it might nowadays work a tad different but the most basic approach should still be the same.

Note that OpenJPA will generate a toString() method for you if the entity class doesn’t have one. In that case we will print the name of the entity and the primary key. And since we know the state of the _loaded fields we will also not force generating a new PK if the entity didn’t already load one from the sequence.
According to Gavin and Vlad Hibernate doesn’t generate any toString(). I have no clue whether EclipseLink does.

For other JPA implementations than Apache OpenJPA I suggest you provide a toString which looks like the following

public String toString() {
    return this.getClass().getSimpleName() + "-" + getId();
}

And not a single attribute more.

equals() and hashCode()

This is where Vlad, Gavin and I really disagree.
My personal opinion is that you shall not write own equals() nor hashCode() methods for entities.

Vlad did write a blog post about equals() and hashCode() in the past https://vladmihalcea.com/2016/06/06/how-to-implement-equals-and-hashcode-using-the-entity-identifier/

As you can see it’s not exactly easy to write a proper equals() and hashCode() method for JPA entities. Even Vlad’s advanced version does have holes. E.g. if you use em.getReference() or em.merge().
In any case, there is a point where Gavin, Vlad and I agree upon: generating equals() and hashCode() with IDEs is totally bollocks for JPA entities. It’s always broken to compare *all* fields. You would simply not be able to update your database rows😉

IF you like to write a equals() method then compare the ids with a fallback on instance equality. And have the hashCode() always return zero as shown in Vlad’s blog.

Another way is to generated a UUID in the constructor or the getId() method. But this is pretty performance intense and also not very nice to handle on the DB side (large Strings as PK consume a lot more storage in the indexes on disk and in memory)

Using ‘natural IDs’ for equals()

That sounds promising. And IF you have a really good natural ID then it’s also a good thing. But most times you don’t.

So what makes a good naturalId? It must adhere to the following criteria:

  • it must be unique
  • it must not change

Sadly most natural IDs you think of are not unique. The social security number (SSN) in most countries? Hah, not unique! Really, there are duplicates in most countries…
Also often used in examples: the ISBN of a book. Toooo bad that those are not unique neither… Sometimes the same ISBN references different books, and sometimes the same book has multiple ISBNs assigned.

What about immutability? Sometimes a customer does not have a SSN yet. Or you simply don’t know it YET. Or you only know it further down the application process. So the SSN is null and only later get’s filled. Or you detect a collision with another person and you have to assign one of them a new SSN (that really happens more often than you think!). There is also the case where the same physical person got multiple SSN (happens more frequent as well).

Many tables also simply don’t have a good natural ID. Romain Manni-Bucau came up with the example of a Blog entry. What natural ID does a blog entry have? The date? -> Not unique. The title? -> can get changed later…

Why do you need equals() and hashCode() at all?

This is a good question. And my answer is: “you don’t !”

The argument why people think it’s needed for JPA entities is because e.g. having a field like:

@OneToMany 
private Set others;

A HashSet internally of course uses equals() and hashCode() but why do you need to provide a custom one? In my opinion the one you implicitly derive from Object.class is perfectly fine. It gives you instance-equality. And since per the JPA specification the EntityManager guarantees that you only get exactly one single entity instance for a row in the database you don’t need more. Doubt it? Then read the JPA specification yourself:

"An EntityManager instance is associated with a persistence context. A persistence context is a set of entity instances in which for any persistent entity identity there is a unique entity instance."

https://docs.oracle.com/javaee/7/api/javax/persistence/EntityManager.html

An exception where instance equality does not work is if you mix managed with detached entity instances. But that is something you should avoid at any cost as my following examples show.

Why you shouldn’t store managed and detached entities in the same Collection

Why would you do that? Instead of storing entities in a Set you can always use a Map. In that case you again don’t need any equals() nor hashCode() for the whole entity. And even then you might get into troubles.

One example is to have a ‘cache’.
Say you have a university management software which has a Course table. Courses get updated only a few times per year and only by some administrative people. But almost every page in the application reads the information. So what could be more reasonable as to simply store the Course in a shared @ApplicationScoped cache as Map for say an hour? Why don’t I use the cache management provided with some JPA containers? Many reasons. First and foremost they are not portable. They are also really tricky to configure (I’m talking about real production, not a sample app!). And you like to have FULL control over the cache!

So, having a cache is really a great idea, but *please* do not store JPA entities in the cache. At least not as long as they are managed. All is fine as long as you only run it locally and click around on your app and only do unit tests. But under heavy load in production (our app had 5 Mio page hits/day average) you will hit the following problem:

The JPA specification does not allow an EntityManager to be used from multiple threads at the same time. As a managed entity is bound to an EntityManager, this limitation also affects the entities themselves.
So while you do the em.find() and later a coursesCache.put(courseId, course) the entity is still in ‘managed’ mode! And under heavy load it *will* happen that another user gets the still managed entity from the cache before it got detached (which happens at the tx commit or request end, depending on your setup). Boooommm it goes…

How can you avoid that? Simply use a view object. Normally the full database entities with all their gory attribute details and sub-tables are not needed on an overview course list anyway. So you better use a ‘new’ query:

CourseListVO couseViewItem 
  = em.createQuery("SELECT NEW org.myproject.Course(c.id, c.name, c.,...) " +
      " FROM Course AS c WHERE...");
cache.put(courseId, courseViewItem);

By using a ‘new Query’ you will get instances which are not managed by the container. And it’s also much faster and consumes less memory btw.

Oh I’m sure there are things which are still not cosidered yet…

PS: this is not an easy topic as you might be able to judge from looking at the involved people. Gavin is the inventor of Hibernate and JPA, Vlad is the current Hibernate maintainer. And I was involved in the DODS DB layer of Lutris Enhydra in the 90s and am a long time Apache OpenJPA committer (and even the current PMC chair).

Applying interceptors to producer methods

Interceptors are really cool if you have a common problem and like to apply it to without making every single colleague copy the same code over again and again to apply a solution over the whole code base.

In my case it was the urge to log out SOAP and REST invocations to other systems. I also like to add a logCorrelationId via HTTP header to each outgoing SOAP call. You can read more about the background over in my other logCorrelation blog post.

I’ll focus on integrating SOAP clients, but you can easily do the same for REST clients as well.

Integrating a SOAP client in an EE project

Usually I create a CDI producer for my SOAP ports. That way I can easily mock them out with a local dummy implementation by just using CDI’s @Specializes or @Alternative. If you combine this with with Apache DeltaSpike @Exclude and the DeltaSpike Configuration system then you can even even enable those Mock via ProjectStage or a configuration setting.

Consider you have a WSDL and you create a SOAP client with the interface CustomerService.

What we like to get from a ‘consumer’ perspective is the following usage:

public class SomeFancyClass {
  private @Inject CustomerService customerService;
  ...
}

Which means you need a CDI producer method, e.g. something like:

@ApplicationScoped
public class CusomerServiceSoapClientProducer {
  @ConfigProperty(name = "myproject.customerService.endpointUrl")
  private String customerServiceEndpointUrl;

  @Produces
  @RequestScoped
  @LogTiming
  public CustomerService createSoapPort() {
    // generated from the WSDL, e.g. via CXF
    CustomerServiceService svc = new CustomerServiceService();
    CustomerServiceServicePort port = svc.getCustomerServiceServicePort();

    // this sets the endpoint URL during producing.
    ((BindingProvider) port).getRequestContext().
           put(BindingProvider.ENDPOINT_ADDRESS_PROPERTY, customerServiceEndpointUrl);

    return port;
  }
}

Side note: the whole class could also be @RequestScoped to get the endpoint URL evaluated on every request. We could of course also use the DeltaSpike ConfigResolver programmatically to gain the same. But the whole point of setting the endpoint URL manually is that we don’t need to change the WSDL and have to recompile the project on every server change. We can also use different endpoints for various boxes (test vs production environments, or different customers) that way.

What is this @LogTiming stuff?

Now it becomes interesting! We now have a SOAP client which looks like a regular CDI bean from a ‘user’ point of view. But we like to get more information about that outgoing call. After all it’s an external system and we have no clue how it behaves in terms of performance. That means we like to protocol each and every SOAP call and log out it’s duration. Of course since we not only have 1 SOAP service client but multiple dozen ones we like to do this via an Interceptor!

@Inherited
@InterceptorBinding
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.TYPE})
public @interface LogTiming {
}

Applying an Interceptor on a producer method?

Of course the code written above DOES work. But it behaves totally different as many of you will guess.
If you apply an interceptor annotation to a producer method, then it will not intercept the calls to the produced bean!
Instead it will just intercept the invocation of the producer method. A producer method gets invoked when the Contextual Instance gets created. For a @Produces @RequestScoped annotated producer method this will happen the first time a method on the produced CDI bean gets called in the very request (or thread for non-servlet request based threads). And exactly this call gets intercepted.

If we would just apply a stopwatch to this interceptor then we would get the info about how long it took to create the soap client. That’s not what we want! We like to get the times from each and every usage of that CustomerService invocation! So what does our LogTiming interceptor do?

Proxying the Proxy

The trick we apply is to to use our LogTiming Interceptor to wrap the produced SOAP port in yet another proxy. And this proxy logs out the request times, etc. As explained before we cannot use CDI interceptors, but we can use java.lang.reflect.Proxy!:

@LogTiming
@Interceptor
public class WebserviceLoggingInterceptor {

    @AroundInvoke
    private Object wrapProxy(InvocationContext ic) throws Exception {
        Object producedInstance = ic.proceed();
        Class[] interfaces = producedInstance.getClass().getInterfaces();
        Class<?> returnType = ic.getMethod().getReturnType();
        return Proxy.newProxyInstance(ClassUtils.getClassLoader(null), interfaces, new LoggingInvocationHandler(producedInstance, returnType));
    }
}

This code will register our reflect Proxy in the CDI context and each time someone calls a method on the injected CustomerService it will hit the LogInvocationHandler. This handler btw can also do other neat stuff. It can pass over the logCorrelationId (explanation see my other blog post linked above) as HTTP header to the outgoing SOAP call.

The final LoggingInvocationHandler looks like the following:

public class LoggingInvocationHandler implements InvocationHandler {
    private static final long SLOW_CALL_THRESHOLD = 100; // ms
 
    private final Logger logger;
    private final T delegate;

    public LoggingInvocationHandler(T delegate, Class loggerClass) {
        this.delegate = delegate;
        this.logger = LoggerFactory.getLogger(loggerClass);
    }

    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        if (EXCLUDED_METHODS.contains(method.getName())) {
            // don't log toString(), hashCode() etc...
            return method.invoke(delegate, args);
        }

        long start = System.currentTimeMillis();

        try {
            // setting log correlation header if any logCorrelationId is set on the thread.
            String logCorrelationId = LogCorrelationUtil.getCorrelationId();
            if (StringUtils.isNotEmpty(logCorrelationId) && delegate instanceof BindingProvider) {
                BindingProvider port = (BindingProvider) delegate;
                Map<String, List> headers = (Map<String, List>) port.getRequestContext().get(MessageContext.HTTP_REQUEST_HEADERS);
                if (headers == null) {
                    headers = new HashMap<>();
                }
                headers.put(LogCorrelationUtil.REQUEST_HEADER_CORRELATION_ID, Collections.singletonList(logCorrelationId));
                port.getRequestContext().put(MessageContext.HTTP_REQUEST_HEADERS, headers);
            }

            // continue with the real call
            return method.invoke(delegate, args);
        }
        finally {
            long duration = System.currentTimeMillis() - start;
            if (duration <= SLOW_CALL_THRESHOLD) {
                logger.info("soapRemoteCall took={} ms service={} method={}", duration, delegate.getClass().getName, method.getName());
            }
            else {
                // log a more detailed msg, e.g. with params
            }
        }
    }

Limitations

Of course this trick only works if the producer method returns an interface! That’s caused by the reflect Proxies are only available for pure interfaces.

I’m trying to remove this limitations by bringing intercepetors for produced instances to CDI-2.0 as well on working on a interceptors spec change to introduce ways to create subclassing proxies as easy as interface proxies. Stay tuned!

What is LogCorrelation?

While working on an article about CDI interceptors on producer methods I mention logCorrelation. I will not go into detail on this topic over at the other blog post as it would be simply too much over there. And this gives a great topic for a separate post anyway. And here we go…

So what is LogCorrelation?

Consider you have a more or less distributed application topology. You might have a server which does maintain customer data. There might be another box handling all the document archive, another one which holds the calculation kernel, etc etc.

Nowadays all people would say that are microservices. 8 years ago all people called it SOA. To be honest I GIVE A SHIT how some sales people name it as all this is around since much longer than I’m working in the industry (which is a whoopie 25 years already). It’s just modular applications talking with each other somehow. Sometimes via SOAP or REST, but maybe even via MessageQueue, shared database tables or file based with batches handling the passing over – to me it doesn’t matter much.

But for all those the problem is the same: Consider a user clicks on some button in his browser or fat client. This triggers an ‘application action’. And this single action might hit the first server, then this server pings another one, etc. Synchronous or asynchronous also doesn’t matter. This might go all over the place in your company and even externally.  At the end something happens and the user most times gets some response. And it is really, REALLY hard to tell what’s wrong and where it went wrong if something doesn’t work as expected or returns wrong results. Often you don’t even have a clue which servers were involved. And if your whole application starts to behave ‘laggy’ then you will have a hard time judging which system you need to tinker with.

Now how cool would it be if you could follow this single action over all the involved servers?

And this is exactly what logCorrelation does!

What is the trick?

The trick is really plain simple. Each ‘action’ gets an own unique logCorrelationId. That might be a UUID for example. The only requirement is that it’s ‘decently’ unique.

If a server gets a request then he checks if there was a logCorrelationId passed to him. If so, then he takes this id and stores it in a ThreadLocal. If there was no id passed, then this is a ‘new’ action and we generate a fresh logCorrelationId. Of course this logCorrelationId will also get set as e.g. HTTP header for all subsequent outgoing HTTP calls on this very thread.

Where do I show the logCorrealationId?

Our applications now all handle this logCorrelationId properly, but where can I look at it? What is the benefit of all this?

At my customers I mainly use Apache log4j as logging backend, (often with slf4j as API). The point is that only log4j (and logback, but with way worse performance) support a nice little feature called MDC which stands for Mapped Diagnostic Context.  It is basically a ThreadLocal<Map<String, String>> which will get logged out in each and every line you log out on this very thread.

This log4j feature can also be accessed via the slf4j API. E.g. in a javax.servlet.Filter

MDC.set("correlationId", logCorrelationId);
MDC.set("sessionId", httpSessionId);
MDC.set("userId", loggedInUser.getId());

For enabling it in the log output you need to configure a ConversionPattern:

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d{ISO8601} [%t] %X{sessionId} %X{userId} %X{correlationId} %-5p %c{2} %m%n"/>
        </layout>
    </appender>

If you logging is configured properly in your company and you funnel all back into log aggregation systems like ELK (OpenSource with commercial support offering) or Splunk (Commercial with limited free offering) then you can now simply follow a single action over all the various systems.

What about non-user requests?

Non user requests can sometimes even be filled with more information. At a few customers we use Camunda BPMN Suite (OpenSource with commercial support). The core has a Thread which basically polls the DB and fetches new tasks to execute from it. Those will then get ‘executed’ in a parallel thread. For those threads we intercept the Executor and fill the logCorrelationId with the camunda jobId which basically is a uuid starting with ‘cam-‘. So once a process task blows up we can exactly figure what went wrong – even on a different server.

Of course this trick is not limited to the process engine…

PS: how does my stuff look like?

Probably it’s also worth sharing my LogCorrelationUtil:

/**
 * Helper for log correlation.
 *
 * @author Mark Struberg
 */
public class LogCorrelationUtil {

    public static final String REQUEST_HEADER_CORRELATION_ID = "X_LOG_CORRELATION_ID";
    public static final String MDC_CORRELATION_ID = "correlationId";

    private LogCorrelationUtil() {
    }

    /**
     * Creates a new log correlation Id ONLY IF there is no existing one!.
     * Takes about 4 uS, because I use a much faster UUID algo
     *
     * @param logEnvironment prefix for the logCorrelationId if a new one has to be created. Determines the environment the uuid got created in.
     * @param existingLogCorrelationId oder {@code null} if there is none yet
     */
    public static String enforceLogCorrelationId(LogEnvironment logEnvironment, String existingLogCorrelationId) {
        if (existingLogCorrelationId != null && existingLogCorrelationId.length() > 0) {
            return existingLogCorrelationId;
        }
        ThreadLocalRandom random = ThreadLocalRandom.current();
        String uuid = new UUID(random.nextLong(), random.nextLong()).toString();

        if (logEnvironment != null) {
            StringBuilder sb = new StringBuilder(60);
            sb.append(logEnvironment);
            sb.append(uuid);
            uuid = sb.toString();
        }
        return uuid;
    }

    /**
     * @return the logCorrelationId for this thread or {@code null}
     */
    public static final String getCorrelationId() {
        return MDC.get(MDC_CORRELATION_ID);
    }

    /**
     * Set the given logCorrelationId for the current Thread.
     */
    public static final void setCorrelationId(String logCorrelationId) {
        MDC.put(MDC_CORRELATION_ID, logCorrelationId);
    }

    /**
     * Clears the logCorrelationId from the current Thread.
     * This method MUST be called at the end of each request 
     * to prevent mem leaks!
     */
    public static final void clearCorrelationId() {
        MDC.remove(MDC_CORRELATION_ID);
    }
}

Being ‘unstoppable’ – a Batchlets tale

How to stop a JBatch Batch

JSR-352 (JBatch) is a great specification. It takes care of many situations a user don’t think about most times. For example how to stop a Batch. But sometimes it cannot relief you from putting some brain into it.

How to trigger a Batch stop?

The JobOperator has a method to stop a specific execution: JobOperator#stop(long executionId).

Of course the JobOperator will not immediately kill the worker thread with this batch but tries to gracefully shut down the Batch.

Stopping a ‘Chunk Step’

First, what is a ‘Chunk’? A chunk is a batch <step> which consists of an ItemReader an optional ItemProcessor and an ItemWriter. A ‘chunk’ defines the transaction size of the processing. Let’s consider a chunk-size of 10. This means that our step processes 10 items and then commits all of them in a single commit.

The processing order is as following
ItemReader, ItemProcessor, ItemReader, ItemProcessor,… until we did read and process our 10 items. After that all the 10 items will get handed over to the ItemWriter to store them somewhere. After that a commit happens and the loop starts over with the next items.

If you call JobOperator#stop(executionId) for a Chunk Step then the loop which invokes the ItemReader, ItemProcessor and ItemWriter will continue with reading and processing the current Item and then hand over all the currently chained Items to the ItemWriter. After that the loop exits gracefully.

That’s nice and clean! But what about Batchlets?

Stopping a ‘Batchlet’

There is a good reason why I write this post today. In the last few weeks we had a few Batchlets which didn’t behave ‘nice’ to our ops team. Those beasts didn’t want to stop working! Of course the problem only occurred in production and not in all the tests done before. Simply because in production we have millions of items to process whereas in the test they just fed in a a few thousand items.

So why didn’t those Batchlets stop?

First we have to understand what a Batchlet is. Opposite to a Chunk Step a Batchlet is a ‘do-it-yourself’ thingy. The JBatch runtime really hands over all the control to your code. It doesn’t even do Transactions for you! It is really all in your hands. Usually such a batchlet contains a processing loop as well:

public class MyBatchlet extends AbstractBatchlet {
  @Override
  public String process() throws Exception {
    List items = readAllItemsToProcess();
    for (MyItem item : items) {
      processAndStoreMyItem();
    }
    return "OK";
  }
}

That’s nice…. but won’t stop for you…

So what is missing? Yes, AbstractBatchlet implements an empty stop() method. And this is often a bad idea…

Our code should better look somehow like the following:

public class MyBatchlet implements Batchlet {
  private volatile boolean shouldStop = false;

  @Override
  public void stop() {
    shouldStop = true;
  }

  @Override
  public String process() throws Exception {
    List items = readAllItemsToProcess();
    for (MyItem item : items) {
      processAndStoreMyItem();
      if (shouldStop) {
        return "STOPPING";
      }
    }
    return "OK";
  }
}

There are a few important details:
1.) the boolean shouldStop field really needs to be volatile. That is because the stop() method gets called from a different thread and otherwise the new value might not be visible to the worker thread. Read up more on volatile over at the excellent Angelika Langers Java Memory Model talk.

2.) I’m thinking about preventing the usage of “extends AbstractBatchlet” via a checkstyle rule. It’s actually not worth having this AbstractBatchlet. People should be aware that they missed the stop() functionality!

JTA vs resource-local performance

A few years ago I did a simple test to compare how JTA handling (via UserTransaction) compares to resource local transaction handling. Back then using JTA had a rather big impact on the performance. Time to repeat this test with a modern EE server.

So I went on and created a very simple JPA sample which does a loop and creates 1000 Customer entries in a simple h2 memdb. I did choose h2 memdb because it’s pretty fast. At least much faster than any production ready DB which stores the stuff on a disk. In the end we like to know the performance of JTA and not bench the database.

My simple sample can be downloaded at https://github.com/struberg/jtabench
To start it just run
$> mvn clean install tomee:run

So far my tests don’t show a huge problem.

When I run the benchmark against the resource-local part (http://localhost:8080/jtabench/customer/nonjta) I get
Resource-Local: 21.6 pages/second.
That means 21600 inserts per second.

If I do the very same benchmark against the JTA part (http://localhost:8080/jtabench/customer/jta) I get about
JTA: 19.0 pages/second.
And please remember that h2 memdb is really fast! Thus with a real database load the difference will simply be negligible.

If you reproduce the test yourself locally then don’t forget to clean the databases inbetween benchmark runs with http://localhost:8080/jtabench/customer/reset . This will delete all temporarily created Customer entries in the dbs.

Note: I’m not quite sure how much optimization geronimo-tx applies if there is only a single DataSource involved. Need to dig that myself. Probably will provide a follow up test with 2++ different databases…

The (mostly) unknown story behind javax.ejb.EJBException

Yesterday I blogged about what impact Exceptions do have on JavaEE transactions in EJB.
But there is another funny EJB Exception mechanism waiting for you to get discovered – the javax.ejb.EJBException.

This handling dates back to the times when EJB was mainly intended to be a competition to NeXT Distributed Objects and Microsoft DCOM. Back in those days it was all about ‘Client-Server Architecture’ and people tried to spread the load to different servers on the network. A single EJB back then needed 4 classes and was inherently remote by default.

Only much later EJBs got a ‘local’ behaviour as well. And only in EJB-3.1 the No-Interface View (NIV) got introduced which made interfaces obsolete and are local-only.
But for a very long time remoting was THE default operation mode of EJBs. So all the behaviour was tailored around this – regardless whether you are really using remoting or are running in the very same JVM.

The impact of remoting

The tricky situation with remote calls is that you cannot be sure that every class is available on the client.

Imagine a server which uses JPA. This might throw a javax.persistence.EntityNotFoundException. But what if the caller – a Swing EJB client app – doesn’t have any JPA classes on it’s classpath?
This will end up in a ClassNotFoundException or NoClassDefFoundException because de-serialisation of the EntityNotFoundException will blow up on the client side.

To avoid this from happening the server will serialize a javax.ejb.EJBException instead of the originally thrown Exception in certain cases. The EJBException will contain the original Exceptions stack trace as pure Strings. So you at least have the information about what was going wrong in a human readable format.

If you like to read up the very details then check out 9.4 Client’s View of Exceptions in the EJB specification.

Switching on the ‘Auto Pilot”

Some containers like e.g. OpenEJB/TomEE contain a dual-strategy. We have a ‘container’ (ThrowableArtifact) which wraps the orignal Throwable plus the String interpretation and sends both informations as fallback over the line.

On the client side the de-serialization logic of ThrowableArtifact first tries to de-serialize the original Exception. Whenever this is possible you will get the originally thrown Exception on the client side. If this didn’t work then we will use the passed information and instead of the original Exception we throw an EJBException with the meta information as Strings.

The impact on your program?

The main impact for you as programmer is that you need to know that you probably not only need to catch the original Exception but also an EJBException. So this really changes the way your code needs to be written.
And of course if you only got the EJBException then you do not exactly know what was really going on. If you need to react on different Exceptions in different ways then you might try to look it up in the exception message but you have no type-safe way anymore. In that case it might be better to catch it on the server side and send an explicit @ApplicationException over the line.

When do I get the EJBException and when do I get the original one?

I’d be happy to have a good answer myself😉

My experience so far is that it is not well enough specified when each of them gets thrown. But there are some certain course grained groups of container behaviour:

  • Container with Auto-Pilot mode; Those containers will always try to give you the original Exception. And only if it is really not technically possible will give you an EJBException. E.g. TomEE works that way.
  • Container who use the original Exception for ‘local’ calls and EJBException for remote calls.
  • Container who will always give you an EJBException – even for local invocations. I have not seen those for quite some time though. Not sure if this is still state of the art?

Any feedback about which container behaves what way is welcome. And obviously also if you think there is another category!