jvm performance question - Java

Hi

I am working on a server which receives a request, processes it and
stores the result in a db. While investigating its performance I noticed
that there is considerable variation in processing time. The data and
amount is the same every time. I logged the different processing times
and found that at least anything having to do with string processing
seemed to have large variations in them. There are others parts that
have variations to, but that might be because of other things than java,
i.e. the db, interprocess communication etc.

Here are two examples of what I am talking about:

storage.dao - Created str buffer with 10000000 chars in 15 millis.
storage.dao - Created 124999 attributes in 318 millis

storage.dao - Created str buffer with 10000000 chars in 201 millis.
storage.dao - Created 124999 attributes in 73 millis

(The complete log is attached, it only contains 10 occurences, but a one
week test I did showed the exact same variations in processing time)

The buffer is a StringBuilder and the creation of the attributes is by
using the StringBuilder to create a SQL COPY statement that can be sent
to the db. The timing is done by reading currentTimeMillis()

I have tried some different things, e.g.
- increasing the os priority of the jvm,
- using the "-server" option in the jvm,
- increased the timer resolution in the os to get accurate readings.

So I am wondering where this variability comes from. I am thinking it
could be because of:
- threading/process costs, i.e. multitasking cause threads to sleep
causing the timer to include sleep time
- the sun jvm not being built for this kind of use,
i.e. semi-hard timing requirements
by semi-hard I mean, where the performance is measured by how many
sequentual operation it can perform per second, multitasking
performance is of little interrest since it will be mostly one
thread doing this work and it needs to be fast, i.e. store as many
attributes as possible per second. (I know I can paralellize the
processing of a single request, but that is another issue)

any other thoughts on the reasons for the variations?


I am running Linux 2.6.20 (kubuntu) with build sun java 1.6.0-b105

the base command is:

nice --adjustment=-1 java -Xms128M -Xmx512M -server ...


regards

tom





2007-11-17 09:57:18 INFO tf.daemon - Starting server.
2007-11-17 09:57:18 DEBUG tf.services - Obtaining name server reference.
2007-11-17 09:57:19 DEBUG tf.services - Creating server POA.
2007-11-17 09:57:19 DEBUG tf.services - Registering server POA.
2007-11-17 09:57:23 INFO tf.services - Received 125000 attributes
2007-11-17 09:57:23 INFO tf.config - Parsing server configuration from conf/test.conf
2007-11-17 09:57:23 DEBUG tf.storage.bds - Creating a new datasource.
2007-11-17 09:57:24 DEBUG tf.domain - Parsed 125000 attributes in 87 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage - Finished creating table in 248 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage - Finished new InsertAttributes in 1 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 24 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage.dao - Created 124999 attributes in 282 milliseconds (string buffer: 1424215 characters).
2007-11-17 09:57:24 DEBUG tf.storage.dao - Converted buffer to String in 4 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 259 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage - Finished inserting data in 573 milliseconds.
2007-11-17 09:57:24 DEBUG tf.storage - Finished creating index in 45 milliseconds.
2007-11-17 09:57:24 INFO tf.domain - Finished adding 125000 attributes in 867 milliseconds.
2007-11-17 09:57:30 INFO tf.services - Received 125000 attributes
2007-11-17 09:57:31 DEBUG tf.domain - Parsed 125000 attributes in 77 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage - Finished creating table in 12 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 38 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage.dao - Created 124999 attributes in 106 milliseconds (string buffer: 1424296 characters).
2007-11-17 09:57:31 DEBUG tf.storage.dao - Converted buffer to String in 4 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 224 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage - Finished inserting data in 374 milliseconds.
2007-11-17 09:57:31 DEBUG tf.storage - Finished creating index in 46 milliseconds.
2007-11-17 09:57:31 INFO tf.domain - Finished adding 125000 attributes in 432 milliseconds.
2007-11-17 09:57:37 INFO tf.services - Received 125000 attributes
2007-11-17 09:57:37 DEBUG tf.domain - Parsed 125000 attributes in 38 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage - Finished creating table in 15 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 15 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage.dao - Created 124999 attributes in 96 milliseconds (string buffer: 1424604 characters).
2007-11-17 09:57:37 DEBUG tf.storage.dao - Converted buffer to String in 4 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 232 milliseconds.
2007-11-17 09:57:37 DEBUG tf.storage - Finished inserting data in 350 milliseconds.
2007-11-17 09:57:38 DEBUG tf.storage - Finished creating index in 103 milliseconds.
2007-11-17 09:57:38 INFO tf.domain - Finished adding 125000 attributes in 469 milliseconds.
2007-11-17 09:57:43 INFO tf.services - Received 125000 attributes
2007-11-17 09:57:43 DEBUG tf.domain - Parsed 125000 attributes in 59 milliseconds.
2007-11-17 09:57:43 DEBUG tf.storage - Finished creating table in 20 milliseconds.
2007-11-17 09:57:43 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:57:43 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:57:44 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 230 milliseconds.
2007-11-17 09:57:44 DEBUG tf.storage.dao - Created 124999 attributes in 73 milliseconds (string buffer: 1424662 characters).
2007-11-17 09:57:44 DEBUG tf.storage.dao - Converted buffer to String in 5 milliseconds.
2007-11-17 09:57:44 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:57:44 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 234 milliseconds.
2007-11-17 09:57:44 DEBUG tf.storage - Finished inserting data in 545 milliseconds.
2007-11-17 09:57:44 DEBUG tf.storage - Finished creating index in 34 milliseconds.
2007-11-17 09:57:44 INFO tf.domain - Finished adding 125000 attributes in 600 milliseconds.
2007-11-17 09:57:50 INFO tf.services - Received 125000 attributes
2007-11-17 09:57:50 DEBUG tf.domain - Parsed 125000 attributes in 63 milliseconds.
2007-11-17 09:57:50 DEBUG tf.storage - Finished creating table in 12 milliseconds.
2007-11-17 09:57:50 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:57:50 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:57:50 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 16 milliseconds.
2007-11-17 09:57:50 DEBUG tf.storage.dao - Created 124999 attributes in 320 milliseconds (string buffer: 1424765 characters).
2007-11-17 09:57:50 DEBUG tf.storage.dao - Converted buffer to String in 4 milliseconds.
2007-11-17 09:57:50 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:57:51 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 209 milliseconds.
2007-11-17 09:57:51 DEBUG tf.storage - Finished inserting data in 551 milliseconds.
2007-11-17 09:57:51 DEBUG tf.storage - Finished creating index in 33 milliseconds.
2007-11-17 09:57:51 INFO tf.domain - Finished adding 125000 attributes in 597 milliseconds.
2007-11-17 09:57:57 INFO tf.services - Received 125000 attributes
2007-11-17 09:57:57 DEBUG tf.domain - Parsed 125000 attributes in 76 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage - Finished creating table in 18 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 236 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage.dao - Created 124999 attributes in 73 milliseconds (string buffer: 1424330 characters).
2007-11-17 09:57:57 DEBUG tf.storage.dao - Converted buffer to String in 5 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 230 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage - Finished inserting data in 545 milliseconds.
2007-11-17 09:57:57 DEBUG tf.storage - Finished creating index in 47 milliseconds.
2007-11-17 09:57:57 INFO tf.domain - Finished adding 125000 attributes in 611 milliseconds.
2007-11-17 09:58:03 INFO tf.services - Received 125000 attributes
2007-11-17 09:58:03 DEBUG tf.domain - Parsed 125000 attributes in 62 milliseconds.
2007-11-17 09:58:03 DEBUG tf.storage - Finished creating table in 12 milliseconds.
2007-11-17 09:58:03 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:58:03 DEBUG tf.storage.dao - Created attribute array in 0 milliseconds.
2007-11-17 09:58:03 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 16 milliseconds.
2007-11-17 09:58:04 DEBUG tf.storage.dao - Created 124999 attributes in 319 milliseconds (string buffer: 1424217 characters).
2007-11-17 09:58:04 DEBUG tf.storage.dao - Converted buffer to String in 4 milliseconds.
2007-11-17 09:58:04 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:58:04 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 211 milliseconds.
2007-11-17 09:58:04 DEBUG tf.storage - Finished inserting data in 552 milliseconds.
2007-11-17 09:58:04 DEBUG tf.storage - Finished creating index in 29 milliseconds.
2007-11-17 09:58:04 INFO tf.domain - Finished adding 125000 attributes in 594 milliseconds.
2007-11-17 09:58:10 INFO tf.services - Received 125000 attributes
2007-11-17 09:58:10 DEBUG tf.domain - Parsed 125000 attributes in 58 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage - Finished creating table in 21 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage.dao - Created attribute array in 1 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 227 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage.dao - Created 124999 attributes in 74 milliseconds (string buffer: 1424451 characters).
2007-11-17 09:58:10 DEBUG tf.storage.dao - Converted buffer to String in 5 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 211 milliseconds.
2007-11-17 09:58:10 DEBUG tf.storage - Finished inserting data in 518 milliseconds.
2007-11-17 09:58:11 DEBUG tf.storage - Finished creating index in 43 milliseconds.
2007-11-17 09:58:11 INFO tf.domain - Finished adding 125000 attributes in 582 milliseconds.
2007-11-17 09:58:16 INFO tf.services - Received 125000 attributes
2007-11-17 09:58:16 DEBUG tf.domain - Parsed 125000 attributes in 48 milliseconds.
2007-11-17 09:58:16 DEBUG tf.storage - Finished creating table in 9 milliseconds.
2007-11-17 09:58:16 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:58:16 DEBUG tf.storage.dao - Created attribute array in 1 milliseconds.
2007-11-17 09:58:17 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 15 milliseconds.
2007-11-17 09:58:17 DEBUG tf.storage.dao - Created 124999 attributes in 318 milliseconds (string buffer: 1424526 characters).
2007-11-17 09:58:17 DEBUG tf.storage.dao - Converted buffer to String in 4 milliseconds.
2007-11-17 09:58:17 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:58:17 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 238 milliseconds.
2007-11-17 09:58:17 DEBUG tf.storage - Finished inserting data in 577 milliseconds.
2007-11-17 09:58:17 DEBUG tf.storage - Finished creating index in 27 milliseconds.
2007-11-17 09:58:17 INFO tf.domain - Finished adding 125000 attributes in 613 milliseconds.
2007-11-17 09:58:23 INFO tf.services - Received 125000 attributes
2007-11-17 09:58:23 DEBUG tf.domain - Parsed 125000 attributes in 58 milliseconds.
2007-11-17 09:58:23 DEBUG tf.storage - Finished creating table in 11 milliseconds.
2007-11-17 09:58:23 DEBUG tf.storage - Finished new InsertAttributes in 0 milliseconds.
2007-11-17 09:58:23 DEBUG tf.storage.dao - Created attribute array in 1 milliseconds.
2007-11-17 09:58:23 DEBUG tf.storage.dao - Created string buffer with 10000000 characters in 201 milliseconds.
2007-11-17 09:58:23 DEBUG tf.storage.dao - Created 124999 attributes in 73 milliseconds (string buffer: 1424551 characters).
2007-11-17 09:58:23 DEBUG tf.storage.dao - Converted buffer to String in 5 milliseconds.
2007-11-17 09:58:23 DEBUG tf.storage.dao - Created buffer stream in 0 milliseconds.
2007-11-17 09:58:24 DEBUG tf.storage.dao - Finished saving to db 124999 attributes in 265 milliseconds.
2007-11-17 09:58:24 DEBUG tf.storage - Finished inserting data in 546 milliseconds.
2007-11-17 09:58:24 DEBUG tf.storage - Finished creating index in 28 milliseconds.
2007-11-17 09:58:24 INFO tf.domain - Finished adding 125000 attributes in 585 milliseconds.