Introducing JDBCMetrics
22 May 2013
I've been working with different Java web applications since the late 90's and when there have been performance issues, I would say that 99% of the time, the problem is the database, or rather how it is used. At my last company (Josh) we had a really good connection pool wrapper, that collected data and made us know exactly what happens to the database. But that code isn't Open Source but there are other solutions out there like JDBCSpy and Log4JDBC that helps you get info. What I'm lacking is getting info per page basis and a better way of colleting the data. That's why I teamed up with Magnus Lundberg & created JDBCMetrics.
Metrics backend
First of all; JDBCMetrics is using Yammers/Coda Hales great Metrics package, to keep track of the metrics. That is cool, because it is very well tested, very low overhead and can report the data to a log/Graphite/Ganglia/JSON and more.
JDBCMetrics collects the following metrics:
- The number of reads & writes per request
- The time spent in read & writes per request
- The total number of database reads
- The total number of database writes
- Number of reads per second (per minute, 5 minutes & 15 minutes)
- Number of writes per second (per minute, 5 minutes & 15 minutes)
- Average/median/percentile query times for reads & for writes
- The number of database reads created for a specific HTTP request
- The number of database writes created for a specific HTTP request
- Statistics about reads & read time per request (average, median, percentile etc)
- Statistics about writes & write times per request (average, median, percentile etc)
You will gets stats both overall and specific per request. To do that, you need to change your JDBCDriver string/Datasource, read how to do it here.
Getting number of database request per HTTP request
To be able to collect data per request, you must setup the JDBCMetricsFilter, you do that first in the chain and you can find the details here. When the filter is up and running you can choose to either log each request & the metrics or fetch the data in the response header.
Metrics in the log
When the logging is configured, it will look something like this:... URL: https://example.com/firstpage/ reads:464 writes:23 readTime: 2001 ms writeTime: 25 ms ... URL: http://example.com/?real=true reads:1708 writes:2 readTime: 21301 ms writeTime: 10 ms ... URL: http://example.com/ reads:2 writes:0 readTime: 40 ms writeTime: 0 ms
Example.com seems to be a read heavy application :) The logs are good if you want to keep track of URL specific information but you will need to go through the data.
Metrics in the response header
You can fetch the data per request, by adding a specific request header, and then you will get back the value in the response headers. In your browser it will look something like this:
nr-of-reads:200 nr-of-writes:0 read-time:2300 write-time:0
It is implemented this way so you easy can propagate the numbers to other tools e.g use it in your continuos integration. Check out the JDBCMetrics for Jenkins plugin if you want to try it out.
Metrics summary
Here is an example of how the summary will look like if you setup the Metrics servlet, serving JSON. It will give you an idea of what kind of data you will collect using JDBCMetrics.
"connectionpool.readorwrite" : {
"wait-for-connection" : {
"type" : "timer",
"duration" : {
"unit" : "milliseconds",
"min" : 0.0,
"max" : 0.0,
"mean" : 0.0,
"std_dev" : 0.0,
"median" : 0.0,
"p75" : 0.0,
"p95" : 0.0,
"p98" : 0.0,
"p99" : 0.0,
"p999" : 0.0
},
"rate" : {
"unit" : "seconds",
"count" : 0,
"mean" : 0.0,
"m1" : 0.0,
"m5" : 0.0,
"m15" : 0.0
}
}
},
"jdbc.read" : {
"read-counts-per-request" : {
"type" : "histogram",
"count" : 83183,
"min" : 0.0,
"max" : 23561.0,
"mean" : 231.48853732132767,
"std_dev" : 524.4286849850237,
"median" : 59.0,
"p75" : 286.75,
"p95" : 871.0,
"p98" : 1667.079999999997,
"p99" : 2014.340000000002,
"p999" : 4538.537000000004
},
"read-time" : {
"type" : "timer",
"duration" : {
"unit" : "milliseconds",
"min" : 0.492218,
"max" : 19688.106567,
"mean" : 2.280825185588168,
"std_dev" : 13.286976540545512,
"median" : 1.184485,
"p75" : 1.355557,
"p95" : 1.8026229499999997,
"p98" : 2.172670539999999,
"p99" : 2.396370910000002,
"p999" : 295.07636368100026
},
"rate" : {
"unit" : "seconds",
"count" : 19308149,
"mean" : 43.741033127820316,
"m1" : 106.93881518440588,
"m5" : 83.31774794755745,
"m15" : 66.43057529214418
},
"read-time-per-request" : {
"type" : "timer",
"duration" : {
"unit" : "milliseconds",
"min" : 5.21222,
"max" : 221221.106567,
"mean" : 10.232323232,
"std_dev" : 13.286976540545512,
"median" : 9.32323,
"p75" : 2.355557,
"p95" : 2.8026229499999997,
"p98" : 5.172670539999999,
"p99" : 10.396370910000002,
"p999" : 995.07636368100026
},
"rate" : {
"unit" : "seconds",
"count" : 19308149,
"mean" : 43.741033127820316,
"m1" : 106.93881518440588,
"m5" : 83.31774794755745,
"m15" : 66.43057529214418
}
},
},
"jdbc.write" : {
"write-counts-per-request" : {
"type" : "histogram",
"count" : 83183,
"min" : 0.0,
"max" : 42.0,
"mean" : 0.9427527259175553,
"std_dev" : 2.2286184648983305,
"median" : 0.0,
"p75" : 1.0,
"p95" : 3.0,
"p98" : 4.0,
"p99" : 4.710000000000036,
"p999" : 19.0
},
"write-time" : {
"type" : "timer",
"duration" : {
"unit" : "milliseconds",
"min" : 0.536404,
"max" : 454.597106,
"mean" : 2.3585642230261286,
"std_dev" : 9.068482382904248,
"median" : 1.3070735,
"p75" : 1.446014,
"p95" : 1.9425782499999997,
"p98" : 2.77765188,
"p99" : 3.8080992300000025,
"p999" : 214.004016876
},
"rate" : {
"unit" : "seconds",
"count" : 80717,
"mean" : 0.1828577635497448,
"m1" : 0.41685499020549865,
"m5" : 0.24844523702006902,
"m15" : 0.2061207361098385
},
"write-time-per-request" : {
"type" : "timer",
"duration" : {
"unit" : "milliseconds",
"min" : 5.536404,
"max" : 1454.597106,
"mean" : 4.3585642230261286,
"std_dev" : 9.068482382904248,
"median" : 10.3070735,
"p75" : 3.446014,
"p95" : 3.9425782499999997,
"p98" : 4.77765188,
"p99" : 8.8080992300000025,
"p999" : 414.004016876
},
"rate" : {
"unit" : "seconds",
"count" : 80717,
"mean" : 0.1828577635497448,
"m1" : 0.41685499020549865,
"m5" : 0.24844523702006902,
"m15" : 0.2061207361098385
}
},
}
If you used the Metrics API before, you will understand the numbers, else here as short explanation: The read-counts-per-request tells us that there has been 83183 HTTP requests. One request generated 23561 read queries (!!!), the median number of reads per request is 59 and the 95 percentile is 871.
How long time the database reads takes are collected in read-time. The median time for all read requests are 1.184485 milliseconds, 19308149 database reads has been performed and last minute (m1) 106.93881518440588 queries was executed.
You can find the project and documentation at Github. The jar is available in Maven.
Written by: Peter Hedenskog