I would be tempted to focus more on those that are in the hundreds than those two at a count of 66.

In terms of the BaseTransaction.getStatus and TransactionSynchronizationRegistryImple.getTransactionStatus, would they happen to be proceeded by anything that implied for certain that they were about to be called. It would be worth finding out why those calls are made so much, there could be a performance optimization there?

I suspect the gets are not that useful (eg the state can be inferred since I believe we log each transaction state change) but the suspend probably is (unless like Marks says you can infer suspend from other log statements)

Knowing that the thread is no longer associated is still useful even without the corresponding resume (but of course we should add that in preference to removing the suspend trace).

I found it odd that the threads were different, but I think the messages could have been picked at random out of the log?

Anyway, definitely we can remove:

TransactionSynchronizationRegistryImple.getTransactionStatus

As that can only end up with an NPE (which I don't think is possible but just covering myself), or the call to:

BaseTransaction.getStatus

I would still like to know why we need to call getStatus 600+ times for a transaction, for JTS that will add 600 RPC per transaction (well, once the tx is completed and before the transaction is started we use a cached value, so it would be at most 600+). Do you know where the calls are coming from and at what stage? Maybe we should only trace if we are about to RPC rather than when we are just returning an int to a caller.

....

I just checked, most of those calls to getTransactionStatus will be returning

javax.transaction.Status.STATUS_NO_TRANSACTION

You can tell from the log if they are returning something else because they are followed by:

TransactionImple.getStatus: javax.transaction.Status.<BLAH>

I think I would just move the debug down to here:

https://github.com/jbosstm/narayana/blob/master/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/BaseTransaction.java#L173

That being said, it is a worrying precedent to remove logging in order that the tool works. But I do take the rationale that it simplifies the log for none-tooled users too.

Just to summarise, the thing I am happy to do is remove "TransactionSynchronizationRegistryImple.getTransactionStatus"

My topic of discussion would be whether it is safe to move the "BaseTransaction.getStatus" to when we are going to query the transaction object as I mentioned might be possible above. The drawback is that if there is no transaction on the thread and a user calls getStatus there is no logging from the transaction manager to assist debugging an issue (well I suppose you could say if the call succeeded the and there was no logging then you would know that it was returning STATUS_NO_TRANSACTION. Possibly you could say the caller should have some additional debug to help them with an issue in that area? I don't see that we call TransactionManager::getStatus internally and rely on that value so the only calls should be from none-JBTM code.

I think I would just move the debug down to here:

https://github.com/jbosstm/narayana/blob/master/ArjunaJTA/jta/classes/com/arjuna/ats/internal/jta/transaction/arjunacore/BaseTransaction.java#L173

 

That being said, it is a worrying precedent to remove logging in order that the tool works. But I do take the rationale that it simplifies the log for none-tooled users too.

I doubt it would ever be useful to know that someone has called getStatus since the actual status should always be inferable from previous log messages.

Also I don't think Paul is doing this to simplify the tool, rather it's an observation that we are doing a lot of logging whose benefits are dubious,

So are you happy to modify your request to:

1. Remove "TransactionSynchronizationRegistryImple.getTransactionStatus"

2. Leave "TransactionSynchronizationRegistryImple.getTransactionKey" as is

3. Leave "TransactionImpleManager.suspend" as is

4. Report "BaseTransaction.getStatus" only when we are not returning a STATUS_NO_TRANSACTION

By my calculations that would leave (there are 47 BaseTransaction.getStatus in the log that would be kept) 179 of the original 1332

You ignored my earlier comment:

I doubt it would ever be useful to know that someone has called getStatus since the actual status should always be inferable from previous log messages.

And why is one status less important than the others?

Well the transaction has no status, it doesn't exist.

So the caller thinks there may be a transaction present otherwise he wouldn't have bothered making the call - I would argue that's more than enough reason to log the situation.