hibernate p6spy problem

Question

I'm trying to get to grips with what hibernate is doing under the hood, and I'm using p6spy as a proxy for the mysql jdbc driver so I can see what's really going to the database. I'm a little confused by the output from p6spy however - grateful for any light!

The problem is this. I'm creating two new objects of class Test1, namely test1a and test1b. The output in my logs is as follows:

Hibernate: 
    /* insert com.play.hibernate1.Test1
        */ insert 
        into
            Test1
            (name, value, id) 
        values
            (?, ?, ?)
1274973057265|1|1|batch|/* insert com.play.hibernate1.Test1 */ insert into Test1 (name, value, id) values (?, ?, ?)|/* insert com.play.hibernate1.Test1 */ insert into Test1 (name, value, id) values ('Test 1', 10, 5)
Hibernate: 
    /* insert com.play.hibernate1.Test1
        */ insert 
        into
            Test1
            (name, value, id) 
        values
            (?, ?, ?)
1274973057265|0|1|batch|/* insert com.play.hibernate1.Test1 */ insert into Test1 (name, value, id) values (?, ?, ?)|/* insert com.play.hibernate1.Test1 */ insert into Test1 (name, value, id) values ('Test 2', 20, 6)
1274973057267|2|1|statement|/* insert com.play.hibernate1.Test1 */ insert into Test1 (name, value, id) values (?, ?, ?)|/* insert com.play.hibernate1.Test1 */ insert into Test1 (name, value, id) values ('Test 2', 20, 6)
1274973057268|0|1|commit||

I can see two 'batch' statements, presumably from calls to the jdbc addBatch api, but what is that '1274973057267|2|1|statement' doing there? It LOOKS like the second insert is getting repeated, but I know it's not or I would see 3 rows in my db and not two, or at least an error.

Why I am I seeing the second insert statement repeated?

If I exclude 'batch' in my spy.properties, I ONLY see this weird, rogue line.

Thanks for any illumination!

Answer 1

Ah - I see the problem, which appears to be due to what I have to say is a rather surprising design decision in p6spy.

Apparently for batched statements, the decision was made to log statements as they are added to the batch, and then show the LAST statement executed when the batch is actually executed! Once you know that's what the tool does, I guess you can understand why it's there, but it's completely confusing and counter-intuitive unless you happen to have read the thread here:

http://sourceforge.net/projects/p6spy/forums/forum/166969/topic/666877

Answer 2

In *spy.propertie*s file, the default property of excludecategories is [info,debug,result,batch], You can exclude the batch category, then you will get what you want.

Answer 3

The tail end of it (513) looks like part of the timestamp