search

LatencyUtils / jRT

jRT measures the response time of a java application to socket-based requests
Other
48 stars 11 forks source link

missing jRT metrics when "Attached" midway thru load test #13

Open eostermueller opened 8 years ago

eostermueller commented 8 years ago

Hello,

Thanks for sharing jRT, this is a unique and great measurement tool.

Not sure what can be done about this, but I've found a problem that I can reproduce readily. If I start a load test that looks like this: JMeter --> Jetty 1 --> Jetty 2 ...where each "-->" is an http connection, ....and once the load is running at steady state, then I attach jRT, ....then all my jRT response time metrics show up as 0's.

But if I attach jRT before I start applying load, then it all works fine..... I'm using the exact same jRT startup arguments for the good and bad run.

If I'm reproducing the problem and then I restart my JMeter test, all the 0.00's in the jRT data change to valid HTTP response times.

If I were a betting man, I'd say that jRT relies on capturing the socket creation to capture good data. But when a connection pool is already warmed up, as in my steady state example, there are no socket creations (by definition of an HTTP connection pool), thus impairing jRT's ability to trace. Here is how I'm starting jRT, but I'm pretty sure these arguments don't impact the issue much: java -Xbootclasspath/a:$MY_CP -jar jRT.jar -pid=$MY_PID -agentargs='-mode=i2o,remote-port=8676,local-port=8676,sample-interval=5000'

Below is the problem data. Note that all the "Interval_Max" times are 0.000.

`"StartTimestamp","Interval_Length","Interval_Max","Interval_Compressed_Histogram"

[StartTime: 1469990446.956 (seconds since epoch), Sun Jul 31 13:40:46 CDT 2016]

0.008,0.461,0.000,HISTggAAACN42pNpmdzIwMDAwQABTBCK+QUQuxnsWMBg/4EBBQAAm+sFqg== 0.469,5.010,0.000,HISTggAAACN42pNpmdzIwMDAwQABTBCK+QUQuxnsWMBg/4EBBQAAm+sFqg== 5.479,5.005,0.000,HISTggAAACN42pNpmdzIwMDAwQABTBCK+QUQuxnsWMBg/4EBBQAAm+sFqg== 10.484,5.003,0.000,HISTggAAACN42pNpmdzIwMDAwQABTBCK+QUQuxnsWMBg/4EBBQAAm+sFqg== 15.487,5.005,0.000,HISTggAAACN42pNpmdzIwMDAwQABTBCK+QUQuxnsWMBg/4EBBQAAm+sFqg== 20.492,5.006,0.000,HISTggAAACN42pNpmdzIwMDAwQABTBCK+QUQuxnsWMBg/4EBBQAAm+sFqg==`

...and here is the good data:

55.299,5.003,3019.899,HISTggAAAFZ42u3YQQmAQBQE0FmtYQgbiBd7CTawwMYwkkcjKCwm8CbvwfDvcxr+sO1rMtc0XTv9+WQZj5rpCgAAAAAAAAAAfFVUAADYMwAAAAAA/Nj7Ry43LkUGhw== 60.302,5.005,3019.899,HISTggAAAGV42u3UUQmAQAwA0J2KKQxhA/HHXoINLGAMI/lpBIUzg6D3Hox9jo1t3bLOEeMWWZVTfdwx9fsWwxkAAAAAAACUIxkB9hwo6M7TS3XTy3195Z+mn80DAAAAAAAAgLK1T24uRAQGlw== 65.307,5.002,3019.899,HISTggAAAG142u3RsQmAMBAF0FPBwhkcwg3Exr0EN3ABx3AkS0dQ0MpGDZbvQfgEAvmX1OM0RHRznPIzivVYfbPM0W4BAAAAAAAAAJAiu+XTubf7r/c/9coSe6f2+3uev/8L7wUAAAAAAADAd9WV5Q7/4Aaj 70.309,5.002,3019.899,HISTggAAAHB42u3QwQmDQBAF0L8GcrGFFGEHIZf0FUgHacAyLMljSkhAT4Lgqsf3YBj4AzMwt/fnlTz6TJqpXcZ/Pbuhz/0bAAAAAAAAAKBOqcyX87JznoP71zSVeXbeKSf/Mwf/BQAAAAAAAACwVTv36w8yoQal 75.311,5.002,3019.899,HISTggAAAGp42u3SsQmEQBAF0NkVTGzhirADMbEv4Tq4BizDkgwtQUEjQfRC5T0Yhg/zs/l8f31EO8Qmb6uY1unqcYhmDgAAAAAAAAB4q3zI6eI+neR8s/dv/6r3NMnLAQAAAAAAAAAvVe27XAAbeAak 80.313,5.006,3019.899,HISTggAAAG142u3PsQmAQAwF0KiFuINDuIHYuJfgBi7gGI5k6QgK2gpeIYi8B+E3SS5Xj9MQ0c1xys8o1qP6Zpmj3QIAAAAAAAAA/ia7ybu+/OF8lvh+JM6l7n36/3jpnrfuBwAAAAAAAAD4mvLKagc84Aak

I used my PR #12 to make sure my filter criteria is ok, see port 8676 info below.

remote-addr:remote-port <-> 127.0.0.1:local-port # /127.0.0.1:59061 <-> 127.0.0.1:8676 === true remote-addr:remote-port <-> 127.0.0.1:local-port # localhost/127.0.0.1:8676 <-> 127.0.0.1:59061 === true 2016-07-31 10:44:43.062 INFO 12028 --- [qtp134999601-73] /__admin : RequestHandlerClass from context returned com.github.tomakehurst.wiremock.http.AdminRequestHandler. Normlized mapped under returned 'null' remote-addr:remote-port <-> 127.0.0.1:local-port # /127.0.0.1:59062 <-> 127.0.0.1:8675 === false remote-addr:remote-port <-> 127.0.0.1:local-port # /127.0.0.1:59063 <-> 127.0.0.1:8676 === true remote-addr:remote-port <-> 127.0.0.1:local-port # localhost/127.0.0.1:8676 <-> 127.0.0.1:59063 === true 2016-07-31 10:44:48.330 INFO 12028 --- [qtp134999601-74] / : RequestHandlerClass from context returned com.github.tomakehurst.wiremock.http.StubRequestHandler. Normlized mapped under returned 'null' remote-addr:remote-port <-> 127.0.0.1:local-port # /127.0.0.1:59064 <-> 127.0.0.1:8675 === false remote-addr:remote-port <-> 127.0.0.1:local-port # localhost/127.0.0.1:8676 <-> 127.0.0.1:59065 === true remote-addr:remote-port <-> 127.0.0.1:local-port # /127.0.0.1:59065 <-> 127.0.0.1:8676 === true remote-addr:remote-port <-> 127.0.0.1:local-port # /127.0.0.1:59066 <-> 127.0.0.1:8675 === false

If you can reproduce this, at a minimum it seems like we need a comment in the doc for this.

Thanks again for a great monitoring tool, I plan on using it a lot. --Erik

fijiol commented 8 years ago

Thank You, for good feedback!

You are absolutely right in the assumption how jRT works:

If I were a betting man, I'd say that jRT relies on capturing the socket creation to capture good data. But when a connection pool is already warmed up, as in my steady state example, there are no socket creations (by definition of an HTTP connection pool), thus impairing jRT's ability to trace.

And yes, this behaviour introduces the mentioned problem... Will think how to fix, or workaround it.