Does a single PerfMonAgent supports multiple Performance Metrics Collectors?

[Thierry Feltin]

Hi,

This is with JMeterPlugins-0.5.2-snapshot2.

In the JMeter test plan, I use 3 Performance Metrics Collectors:
1 for CPU (total + multiple processes)
1 for memory (multiple process and metrics)
1 for disks

When only a single Performance Metrics Collector is enabled, then it
works perfectly.
By enabling 2 collectors, then one is fine, but not the second one and
the whole JMeter test is stopped.
This is reproducible by enabling 2 or 3 collectors. Then back to 1 and
it works.

In ServerAgent logs, there is an UnsupportedOperationException

A work around would be to launch several ServerAgent but it would be
better to have only one per server.
What do you think?

Thierry

This is the ServerAgent logs in DEBUG around the exception:
...
DEBUG 2012-03-29 17:58:06.745 [kg.apc.p] (): Command line is:
DEBUG 2012-03-29 17:58:06.745 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=30 cap=1024]
DEBUG 2012-03-29 17:58:06.745 [kg.apc.p] (): Command line is:
metrics:disks i/o:fs=:writes

DEBUG 2012-03-29 17:58:06.745 [kg.apc.p] (): Got command line:
metrics:disks i/o:fs=:writes
DEBUG 2012-03-29 17:58:06.745 [kg.apc.p] (): Creating metric: disks
i/o with params: fs=:writes
DEBUG 2012-03-29 17:58:06.746 [kg.apc.p] (): Disk metric type: 6
DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Have metric object:
kg.apc.perfmon.metrics.DiskIOMetric@a18aa2
DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Done executing command
DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Command line is:
INFO 2012-03-29 17:58:06.757 [kg.apc.p] (): Accepting new TCP
connection
DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Creating new metric
getter
DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=6 cap=1024]
DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Command line is: name

DEBUG 2012-03-29 17:58:06.757 [kg.apc.p] (): Got command line: name
ERROR 2012-03-29 17:58:06.758 [kg.apc.p] (): Error executing command
java.lang.UnsupportedOperationException: Unknown command [4]: 'name'
at
kg.apc.perfmon.PerfMonMetricGetter.processCommand(PerfMonMetricGetter.java:
86)
at
kg.apc.perfmon.PerfMonMetricGetter.processNextCommand(PerfMonMetricGetter.java:
100)
at kg.apc.perfmon.PerfMonWorker.read(PerfMonWorker.java:203)
at kg.apc.perfmon.PerfMonWorker.processCommands(PerfMonWorker.java:
97)
at kg.apc.perfmon.AgentTool.processParams(AgentTool.java:72)
at kg.apc.cmdtools.PluginsCMD.processParams(PluginsCMD.java:63)
at kg.apc.cmdtools.PluginsCMD.processParams(PluginsCMD.java:23)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:597)
at kg.apc.cmd.UniversalRunner.main(UniversalRunner.java:149)
DEBUG 2012-03-29 17:58:08.208 [kg.apc.p] (): Building metrics
DEBUG 2012-03-29 17:58:08.209 [kg.apc.p] (): Metrics line:
0.001050348986921461 1.2024671857101417 0.0 0.013755717431814331
0.030663413973029748

DEBUG 2012-03-29 17:58:08.210 [kg.apc.p] (): Building metrics
DEBUG 2012-03-29 17:58:08.211 [kg.apc.p] (): Metrics line:
2.344534016E9

[Andrey Pohilko]

That's frequent user error. You're trying to connect to new perfmon 5.1 with old JMeter Plugin version. Upgrade all your JMeter Plugins installations.

Seems second and third JMeters have old plugins pack

четверг, 29 марта 2012 г. 20:13:15 UTC+4 пользователь Thierry Feltin написал:

[Thierry Feltin]

I double checked. All JMeter Plugins are up-to-date = 0.5.2 (as
displayed in the JMeter UI).
Each one works fine when only a single one is used at a time.
The error pops up when there are multiple ones enabled at a time.
Also, it seems to be more easy to reproduce when the Performance
Metrics collectors have more than 1 metrics each (4 to 10 metrics
each) .

Thierry

[Andrey Pohilko]

And what do you have in your jmeter.log for that situation?

пятница, 30 марта 2012 г. 16:27:32 UTC+4 пользователь Thierry Feltin написал:

[Thierry Feltin]

The agent is started with: startAgent.bat --udp-port 0 --loglevel
debug

In JMeter.log, I have:

2012/03/30 17:09:56 INFO - jmeter.engine.StandardJMeterEngine:
Running the test!
2012/03/30 17:09:56 INFO - kg.apc.perfmon.client.TransportFactory:
Can't connect UDP transport for host: localhost/127.0.0.1:4444
java.io.IOException: Agent is unreachable via UDP
at
kg.apc.perfmon.client.TransportFactory.getTransport(TransportFactory.java:
34)
at
kg.apc.jmeter.perfmon.PerfMonCollector.getConnector(PerfMonCollector.java:
203)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnector(PerfMonCollector.java:
185)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnectors(PerfMonCollector.java:
149)
at
kg.apc.jmeter.perfmon.PerfMonCollector.testStarted(PerfMonCollector.java:
107)
at
org.apache.jmeter.reporters.ResultCollector.testStarted(ResultCollector.java:
275)
at
org.apache.jmeter.engine.StandardJMeterEngine.notifyTestListenersOfStart(StandardJMeterEngine.java:
277)
at
org.apache.jmeter.engine.StandardJMeterEngine.run(StandardJMeterEngine.java:
420)
at java.lang.Thread.run(Thread.java:619)

2012/03/30 17:09:56 INFO - kg.apc.perfmon.client.TransportFactory:
Can't connect UDP transport for host: localhost/127.0.0.1:4444
java.io.IOException: Agent is unreachable via UDP
at
kg.apc.perfmon.client.TransportFactory.getTransport(TransportFactory.java:
34)
at
kg.apc.jmeter.perfmon.PerfMonCollector.getConnector(PerfMonCollector.java:
203)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnector(PerfMonCollector.java:
185)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnectors(PerfMonCollector.java:
149)
at
kg.apc.jmeter.perfmon.PerfMonCollector.testStarted(PerfMonCollector.java:
107)
at
org.apache.jmeter.reporters.ResultCollector.testStarted(ResultCollector.java:
275)
at
org.apache.jmeter.engine.StandardJMeterEngine.notifyTestListenersOfStart(StandardJMeterEngine.java:
277)
at
org.apache.jmeter.engine.StandardJMeterEngine.run(StandardJMeterEngine.java:
420)
at java.lang.Thread.run(Thread.java:619)

2012/03/30 17:09:56 INFO - kg.apc.perfmon.client.TransportFactory:
Can't connect UDP transport for host: localhost/127.0.0.1:4444
java.io.IOException: Agent is unreachable via UDP
at
kg.apc.perfmon.client.TransportFactory.getTransport(TransportFactory.java:
34)
at
kg.apc.jmeter.perfmon.PerfMonCollector.getConnector(PerfMonCollector.java:
203)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnector(PerfMonCollector.java:
185)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnectors(PerfMonCollector.java:
149)
at
kg.apc.jmeter.perfmon.PerfMonCollector.testStarted(PerfMonCollector.java:
107)
at
org.apache.jmeter.reporters.ResultCollector.testStarted(ResultCollector.java:
275)
at
org.apache.jmeter.engine.StandardJMeterEngine.notifyTestListenersOfStart(StandardJMeterEngine.java:
277)
at
org.apache.jmeter.engine.StandardJMeterEngine.run(StandardJMeterEngine.java:
420)
at java.lang.Thread.run(Thread.java:619)

2012/03/30 17:09:57 INFO - kg.apc.perfmon.client.TransportFactory:
Can't connect TCP transport for host: localhost/127.0.0.1:4444
java.io.IOException: Agent is unreachable via TCP
at
kg.apc.perfmon.client.TransportFactory.getTransport(TransportFactory.java:
43)
at
kg.apc.jmeter.perfmon.PerfMonCollector.getConnector(PerfMonCollector.java:
203)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnector(PerfMonCollector.java:
185)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnectors(PerfMonCollector.java:
149)
at
kg.apc.jmeter.perfmon.PerfMonCollector.testStarted(PerfMonCollector.java:
107)
at
org.apache.jmeter.reporters.ResultCollector.testStarted(ResultCollector.java:
275)
at
org.apache.jmeter.engine.StandardJMeterEngine.notifyTestListenersOfStart(StandardJMeterEngine.java:
277)
at
org.apache.jmeter.engine.StandardJMeterEngine.run(StandardJMeterEngine.java:
420)
at java.lang.Thread.run(Thread.java:619)

2012/03/30 17:09:57 INFO - kg.apc.perfmon.client.TransportFactory:
Can't connect UDP transport for host: localhost/127.0.0.1:4444
java.io.IOException: Agent is unreachable via UDP
at
kg.apc.perfmon.client.TransportFactory.getTransport(TransportFactory.java:
34)
at
kg.apc.jmeter.perfmon.PerfMonCollector.getConnector(PerfMonCollector.java:
203)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnector(PerfMonCollector.java:
185)
at
kg.apc.jmeter.perfmon.PerfMonCollector.initiateConnectors(PerfMonCollector.java:
149)
at
kg.apc.jmeter.perfmon.PerfMonCollector.testStarted(PerfMonCollector.java:
107)
at
org.apache.jmeter.reporters.ResultCollector.testStarted(ResultCollector.java:
275)
at
org.apache.jmeter.engine.StandardJMeterEngine.notifyTestListenersOfStart(StandardJMeterEngine.java:
277)
at
org.apache.jmeter.engine.StandardJMeterEngine.run(StandardJMeterEngine.java:
420)
at java.lang.Thread.run(Thread.java:619)


ServerAgent log at the same time:

DEBUG 2012-03-30 17:09:57.250 [kg.apc.p] (): Got command line:

metrics:disks i/o:fs=:writes

DEBUG 2012-03-30 17:09:57.250 [kg.apc.p] (): Creating metric: disks

i/o with params: fs=:writes

DEBUG 2012-03-30 17:09:57.250 [kg.apc.p] (): Disk metric type: 6
DEBUG 2012-03-30 17:09:57.259 [kg.apc.p] (): Have metric object:
kg.apc.perfmon.metrics.DiskIOMetric@14fe5c
DEBUG 2012-03-30 17:09:57.259 [kg.apc.p] (): Done executing command
DEBUG 2012-03-30 17:09:57.259 [kg.apc.p] (): Command line is:
INFO 2012-03-30 17:09:57.259 [kg.apc.p] (): Accepting new TCP
connection
DEBUG 2012-03-30 17:09:57.260 [kg.apc.p] (): Creating new metric
getter
DEBUG 2012-03-30 17:09:57.260 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=6 cap=1024]
DEBUG 2012-03-30 17:09:57.260 [kg.apc.p] (): Command line is: name

DEBUG 2012-03-30 17:09:57.260 [kg.apc.p] (): Got command line: name
ERROR 2012-03-30 17:09:57.260 [kg.apc.p] (): Error executing command

java.lang.UnsupportedOperationException: Unknown command [4]: 'name'
at
kg.apc.perfmon.PerfMonMetricGetter.processCommand(PerfMonMetricGetter.java:
86)
at
kg.apc.perfmon.PerfMonMetricGetter.processNextCommand(PerfMonMetricGetter.java:
100)
at kg.apc.perfmon.PerfMonWorker.read(PerfMonWorker.java:203)
at kg.apc.perfmon.PerfMonWorker.processCommands(PerfMonWorker.java:
97)
at kg.apc.perfmon.AgentTool.processParams(AgentTool.java:72)
at kg.apc.cmdtools.PluginsCMD.processParams(PluginsCMD.java:63)
at kg.apc.cmdtools.PluginsCMD.processParams(PluginsCMD.java:23)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:
39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:597)
at kg.apc.cmd.UniversalRunner.main(UniversalRunner.java:149)

DEBUG 2012-03-30 17:09:58.966 [kg.apc.p] (): Building metrics
DEBUG 2012-03-30 17:09:58.967 [kg.apc.p] (): Metrics line:
0.008290703827835597 1.7321109550871572 8.819897689186806E-4
0.0312206020696143 0.06326434619002823

DEBUG 2012-03-30 17:09:58.968 [kg.apc.p] (): Building metrics
DEBUG 2012-03-30 17:09:58.969 [kg.apc.p] (): Metrics line:
1.378770944E9

DEBUG 2012-03-30 17:09:58.969 [kg.apc.p] (): Building metrics
DEBUG 2012-03-30 17:09:58.975 [kg.apc.p] (): Metrics line: 0.0

DEBUG 2012-03-30 17:09:59.967 [kg.apc.p] (): Building metrics
DEBUG 2012-03-30 17:09:59.967 [kg.apc.p] (): Metrics line: 0.0
0.7887323943661971 0.0 0.015 0.0

[Andrey Pohilko]

Notice the jmeter.log record "kg.apc.perfmon.client.TransportFactory: 

Can't connect TCP transport for host: localhost/127.0.0.1:4444 
java.io.IOException: Agent is unreachable via TCP"

It mans client tried to connect to local port, but failed. That's why it falls back to old agent client code and suddenly it succeeds to connect. You may have some problems with your local network.

Could you try running telnet 127.0.0.1 4444 and writing him "test"?

пятница, 30 марта 2012 г. 19:12:48 UTC+4 пользователь Thierry Feltin написал:

[Thierry Feltin]

Sure.
I gave a try with telnet 127.0.0.1 4444 and I got a "Yep" answer
The related ServerAgent.log is below.

2 clients are connecting fine but 1 is rejected. I really think this
is related to the synchronous start of the 3 client plugins at the
same time in JMeter.
Perhaps this would be easier to see if I could add some thread info in
the ServerAgent.log?

Thierry

DEBUG 2012-04-02 13:26:44.334 [kg.apc.p] (): Start accepting
connections
INFO 2012-04-02 13:26:44.342 [kg.apc.p] (): Binding TCP to 4444
INFO 2012-04-02 13:27:50.115 [kg.apc.p] (): Accepting new TCP
connection
DEBUG 2012-04-02 13:27:50.115 [kg.apc.p] (): Creating new metric
getter
DEBUG 2012-04-02 13:27:51.423 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=1 cap=1024]
DEBUG 2012-04-02 13:27:51.424 [kg.apc.p] (): Command line is: t
DEBUG 2012-04-02 13:27:51.567 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=1 cap=1024]
DEBUG 2012-04-02 13:27:51.567 [kg.apc.p] (): Command line is: te
DEBUG 2012-04-02 13:27:51.743 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=1 cap=1024]
DEBUG 2012-04-02 13:27:51.743 [kg.apc.p] (): Command line is: tes
DEBUG 2012-04-02 13:27:51.855 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=1 cap=1024]
DEBUG 2012-04-02 13:27:51.855 [kg.apc.p] (): Command line is: test
DEBUG 2012-04-02 13:27:52.527 [kg.apc.p] (): Read:
java.nio.DirectByteBuffer[pos=0 lim=2 cap=1024]
DEBUG 2012-04-02 13:27:52.527 [kg.apc.p] (): Command line is: test

DEBUG 2012-04-02 13:27:52.527 [kg.apc.p] (): Got command line: test
INFO 2012-04-02 13:27:52.527 [kg.apc.p] (): Yep, we received the
'test' command
DEBUG 2012-04-02 13:27:52.527 [kg.apc.p] (): Done executing command
DEBUG 2012-04-02 13:27:52.528 [kg.apc.p] (): Command line is:

> ...
>
> read more »

[Andrey Pohilko]

There's single thread serving all the clients... I do tests with multiple Collectorts at localhost and everything's ok. For now I have no idea where to look for the problem.

понедельник, 2 апреля 2012 г. 17:26:45 UTC+4 пользователь Thierry Feltin написал:

[Thierry Feltin]

Thanks,
I'll give a try on another machine to see if I can reproduce and then
let you know the results.

> ...
>
> read more »