search

calimero-project / calimero-server

KNXnet/IP server for KNX IP, KNX (RF) USB, FT1.2, and TP-UART
Other
53 stars 17 forks source link

Sending commands is slow #5

Closed Jay-El66 closed 4 years ago

Jay-El66 commented 4 years ago

Running Calimero on an rPi3B attached to an ABB STOTZ-KONTAKT GmbH KNX-USB

Moved to Calimero after KNXD didn't work with my USB device anymore at all, but:

Trying to switch something on or off takes 5 to 6 seconds. knxtools write "14/5/73" switch on -m knxip 192.168.1.18

Also see: https://michlstechblog.info/blog/eib-knx-knxnet-ip-gateway-with-calimero-server-on-raspberry-pi-orange-pi-pc/

bmalinowsky commented 4 years ago

Most of that time comes from loading the runtime environment, which is done for every invocation of a command. For a short command this is quite the time overhead.

You can test if the actual read or write is slow by starting the group monitor and then issue the commands:

knxtools groupmon 192.168.1.18 write 14/5/73 switch on w 1/2/3 ... r 1/2/3 ...

You can try java class-data sharing to speed up the launch times:

sudo java -Xshare:dump

This creates an archive which is memory mapped by the jvm instead of class loading.

(Similar, this can be done for calimero jars). On my (old) raspberry this shaves off about 1.5 seconds.

Why are you setting the medium to IP -m knxip, the usb device talks to TP1, no?

Jay-El66 commented 4 years ago

Thanks,

sudo java -Xshare:dump doesn't change much

Using groupmon I can confirm that the actual write is slow.

I'm using -m knxip because that's the only way I can get it to work. It does talk to TP1. But I guess that means just knxtools write 14/5/73 switch on Should work, but it doesn't.

I probably have the syntax wrong, but from the info here I just cannot deduct the correct syntax.

bmalinowsky commented 4 years ago

@Jay-El66 thank you! What version of calimero are you using? I.e., in the calimero script, is the branch set to release/2.4 or master.

If you installed using the default script settings, in /etc/calimero/simplelogger.properties can you change the log level to org.slf4j.simpleLogger.defaultLogLevel=trace .

Regarding the -m option: if you run the command without the -m option what does it show? If the command doesn't work, this could be a parsing error of the tool (and not related to any device).

knxtools write 14/5/73 switch on does not have the server address, so that won't work. But assuming it has the server address, that should work.

Anyways, you never need to quote a knx address like "14/5/73" on the command line (no white space in there)

Are you using time for the measurements and can you post the trace log together with the real time output? E.g., time knxtools ...

The question still is (because you posted this for the server), if the delay occurs with the tools or with the server.

bmalinowsky commented 4 years ago

For comparison, here are (single) observations for both 2.4 and 2.5 (with class data sharing off/on)
release/2.4

time knxtools write "14/5/73" switch on -m knxip 192.168.10.164
21:49:56:963 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.10.164:3671 - establish connection from /192.168.10.164:54696 to /192.168.10.164:3671
21:49:57:036 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.10.164:3671 - connection established (channel 7)
21:49:57:050 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.10.164:3671 - establish connection from /192.168.10.164:48953 to /192.168.10.164:3671
21:49:57:063 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.10.164:3671 - connection established (channel 8)
write to 14/5/73 successful
21:49:58:220 INFO calimero.process.communication 192.168.10.164:3671 - detached from link 192.168.10.164:3671
21:49:58:231 INFO calimero.link.192.168.10.164:3671 - link closed

real    0m3.696s
user    0m4.332s
sys 0m0.188s

echo $KNXTOOLS_JVM_OPTS
-Xshare:on

time knxtools write "14/5/73" switch on -m knxip 192.168.10.164
21:51:06:322 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.10.164:3671 - establish connection from /192.168.10.164:46268 to /192.168.10.164:3671
21:51:06:392 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.10.164:3671 - connection established (channel 9)
21:51:06:405 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.10.164:3671 - establish connection from /192.168.10.164:43900 to /192.168.10.164:3671
21:51:06:415 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.10.164:3671 - connection established (channel 10)
write to 14/5/73 successful
21:51:07:545 INFO calimero.process.communication 192.168.10.164:3671 - detached from link 192.168.10.164:3671
21:51:07:557 INFO calimero.link.192.168.10.164:3671 - link closed

real    0m3.086s
user    0m3.833s
sys 0m0.098s

master (2.5)

time knxtools write "14/5/73" switch on 192.168.10.164
22:18:04:088 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.10.164:3671 - connection established (data endpoint 192.168.10.164:59461, channel 17, tunneling address 1.1.129)
22:18:04:132 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.10.164:3671 - connection established (data endpoint 192.168.10.164:52135, channel 18)
write to 14/5/73 successful
22:18:06:023 INFO calimero.process.communication 192.168.10.164:3671 - detached from link 192.168.10.164:3671
22:18:06:038 INFO calimero.link.192.168.10.164:3671 - link closed

real    0m4.709s
user    0m5.880s
sys 0m0.321s

echo $KNXTOOLS_JVM_OPTS
-Xshare:off

time knxtools write "14/5/73" switch on 192.168.10.164
22:18:39:585 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.10.164:3671 - connection established (data endpoint 192.168.10.164:51471, channel 19, tunneling address 1.1.129)
22:18:39:633 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.10.164:3671 - connection established (data endpoint 192.168.10.164:43229, channel 20)
write to 14/5/73 successful
22:18:41:579 INFO calimero.process.communication 192.168.10.164:3671 - detached from link 192.168.10.164:3671
22:18:41:597 INFO calimero.link.192.168.10.164:3671 - link closed

real    0m5.533s
user    0m6.697s
sys 0m0.313s
Jay-El66 commented 4 years ago

Thx again.

I seem to have 2.5.

It takes between 4 and 7.6 seconds for a command (read or write). After a reboot and a new: sudo java -Xshare:dump it's

/etc/calimero/simplelogger.properties does not exist. I did however find the following file: /etc/maven/logging/simplelogger.properties

time knxtools write 14/5/73 switch on -m knxip 192.168.1.18 15:52:30:285 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.1.18:3671 - establish connection from /192.168.1.18:51730 to /192.168.1.18:3671 15:52:30:326 INFO calimero.knxnetip.KNXnet/IP Tunneling 192.168.1.18:3671 - connection established (channel 7) 15:52:30:334 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.1.18:3671 - establish connection from /192.168.1.18:35166 to /192.168.1.18:3671 15:52:33:448 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.1.18:3671 - connection established (channel 8) write to 14/5/73 successful 15:52:36:128 INFO calimero.process.communication 192.168.1.18:3671 - detached from link 192.168.1.18:3671 15:52:36:135 INFO calimero.link.192.168.1.18:3671 - link closed

real 0m6.974s user 0m2.294s sys 0m0.118s

time knxtools write 14/5/73 switch on 15:56:39:565 ERROR calimero.tools.ProcComm - tool options tuwien.auto.calimero.KNXIllegalArgumentException: specify either IP host, serial port, or device at tuwien.auto.calimero.tools.ProcComm.parseOptions(ProcComm.java:920) at tuwien.auto.calimero.tools.ProcComm.(ProcComm.java:188) at tuwien.auto.calimero.tools.ProcComm.main(ProcComm.java:258) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.base/java.lang.reflect.Method.invoke(Method.java:566) at tuwien.auto.calimero.tools.Main.main(Main.java:117)

real 0m0.929s user 0m0.988s sys 0m0.071s

KNXTOOLS_JVM_OPTS is empty

bmalinowsky commented 4 years ago

I forgot that the logging config is not setup automatically in the script; you can achieve the same by typing export KNXTOOLS_JVM_OPTS="-Dorg.slf4j.simpleLogger.defaultLogLevel=trace", and then running knxtools.

But I see where the delay is: there is a 3 second wait opening the device management connection:

15:52:30:334 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.1.18:3671 - establish connection from /192.168.1.18:35166 to /192.168.1.18:3671
15:52:33:448 INFO calimero.knxnetip.KNXnet/IP DevMgmt 192.168.1.18:3671 - connection established (channel 8)

That's the culprit.

time knxtools write 14/5/73 switch on is missing the server address of your knx server. Since your knx server has the IP address 192.168.1.18, the command is time knxtools write 14/5/73 switch on 192.168.1.18.

If you have routing enabled, you can also use knxtools write 14/5/73 switch on 224.0.23.12.

Jay-El66 commented 4 years ago

Wow, using 224.0.23.12 brings the time down to less than 2 seconds! Huge improvement over 7 seconds. Super happy.

knxtools write 14/5/73 switch on -m knxip 192.168.1.18

6.9 seconds

knxtools write 14/5/73 switch on -m knxip 224.0.23.12

1.7 seconds

Many, many thanks!

bmalinowsky commented 4 years ago

For the record, you can also use a tcp connection, and see if this is fast enough. For example:

time knxtools write 1/1/1 switch on --tcp 192.168.10.164