Platform information:
- Hardware: Raspberry 3
- OS: raspbian VERSION=10 (buster)
- Java Runtime Environment: openjdk 11.0.18 2023-01-17 - build 11.0.18+10-post-Raspbian-1deb10u1
- openHAB version: 3.4.2-1
- Issue of the topic:
OH 3.4. fails after a few days….
First it only gets slow or a few metrics are no up to date anymore. I also get “too many open files” and later I can even not access the raspberry anymore. Please help me to troubleshoot and to figure out the problem area. How can I drill down to a specific binding, rules etc. etc??
Openhab.log:
Like:
2023-03-07 07:37:03.033 [INFO ] [nhab.core.model.script.E3dc-pw-avail] - Mode3 - Electricity generated + Battery charging ongoing - NetzbezugAVG:54 BattPct:1 BatCharging:291
2023-03-07 07:37:03.138 [WARN ] [lipse.jetty.server.AbstractConnector] –
java.io.IOException: Too many open files
at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) ~[?:?]
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:533) ~[?:?]
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:285) ~[?:?]
at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:388) ~[bundleFile:9.4.46.v20220331]
at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:704) [bundleFile:9.4.46.v20220331]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.46.v20220331]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.46.v20220331]
at java.lang.Thread.run(Thread.java:829) [?:?]
2023-03-07 07:37:04.459 [WARN ] [lipse.jetty.server.AbstractConnector] -
java.io.IOException: Too many open files
at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method) ~[?:?]
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:533) ~[?:?]
at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:285) ~[?:?]
at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:388) ~[bundleFile:9.4.46.v20220331]
at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:704) [bundleFile:9.4.46.v20220331]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.46.v20220331]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.46.v20220331]
at java.lang.Thread.run(Thread.java:829) [?:?]
CPU is quite low and I already replaced the SDCard to be on the save side but no improvement.
I monitored the count of open files etc. via lsof only for openhab java process via
“lsof -p $(pgrep -f java.openhab) | wc –l” and could see for example below increase after a reboot:
See lsof_oh_java_process.jpg
Basically from about 400 to 20.000 within 2 days!
If I look at the full lsof output (~ 500MB !), I can see many many pipe & eventpoll
pi@otto2:~/collectRe/colOpenFiles sudo lsof > colOpenFiles_all_07042023_1810.txt
#PID 696 is openhab:
pi@otto2:~/collectRe/colOpenFiles $ ps -ef |grep 696
openhab 696 1 8 Apr05 ? 04:12:58 /usr/bin/java -XX:-UsePerfData -Dopenhab.home=/usr/share/openhab -Dopenhab.conf=/etc/openhab -Dopenhab.runtime=/usr/share/openhab/runtime -Dopenhab.userdata=/var/lib/openhab -Dopenhab.logdir=/var/log/openhab -Dfelix.cm.dir=/var/lib/openhab/config -Djava.library.path=/var/lib/openhab/tmp/lib -Djetty.host=0.0.0.0 -….
#Count of pipe in lsof output for openhab’s java PID
pi@otto2:~/collectRe/colOpenFiles $ grep “java 696” colOpenFiles_all_07042023_1810.txt |grep -c “pipe”
3245255
#Count of eventpoll in lsof output for openhab’s java PID
pi@otto2:~/collectRe/colOpenFiles $ grep “java 696” colOpenFiles_all_07042023_1810.txt |grep -c “eventpoll”
1622637
Only a lsof |wc –l returns about 5.043.055 so OH java eventpoll+pipe are already causing 97% of all lsof rows.
Any idea how to further troubleshoot this?
root@otto2:/home/pi/collectRe/colOpenFiles# grep 696 colOpenFiles_all_07042023_1810.txt |grep pipe |awk ‘{print $4}’ |uniq -c |sort -nr
210432 HttpClien
131520 OH-httpCl
118368 HttpClien
105216 ServletMo
78912 qtp306052
65760 OH-httpCl
52608 OH-rule-e
39456 upnp-main
System was working fine for a long time but this started sometimes after upgrade from 2.5.12 to 3.4.2-1
Thanks a lot for any support/guidance to point me in the right direction!!
Regards,
Tom
PS: A few more infos:
dpkg-query –l
…
ii openhab 3.4.2-1 all openhab
rc openhab2 2.5.12-1 all openhab2
ii openjdk-11-jdk:armhf 11.0.18+10-1~deb10u1 armhf OpenJDK Development Kit (JDK)
ii openjdk-11-jdk-headless:armhf 11.0.18+10-1~deb10u1 armhf OpenJDK Development Kit (JDK) (headless)
ii openjdk-11-jre:armhf 11.0.18+10-1~deb10u1 armhf OpenJDK Java runtime, using Hotspot JIT
ii openjdk-11-jre-headless:armhf 11.0.18+10-1~deb10u1 armhf OpenJDK Java runtime, using Hotspot JIT (headless)
OS: raspbian VERSION=“10 (buster)”
root@otto2:/home/pi# /usr/bin/java --version
openjdk 11.0.18 2023-01-17
OpenJDK Runtime Environment (build 11.0.18+10-post-Raspbian-1deb10u1)
OpenJDK Server VM (build 11.0.18+10-post-Raspbian-1deb10u1, mixed mode)
root@otto2:/home/pi/collectRe/colOpenFiles# head colOpenFiles_all_07042023_1810.txt
COMMAND PID TID TASKCMD USER FD TYPE DEVICE SIZE/OFF NODE NAME
…
java 696 836 OH-rule-a openhab 1454u a_inode 0,12 0 6848 [eventpoll]
java 696 836 OH-rule-a openhab 1455r FIFO 0,11 0t0 6807466 pipe
java 696 836 OH-rule-a openhab 1456w FIFO 0,11 0t0 6807466 pipe
java 696 836 OH-rule-a openhab 1457u a_inode 0,12 0 6848 [eventpoll]
java 696 836 OH-rule-a openhab 1458r FIFO 0,11 0t0 6807467 pipe
java 696 836 OH-rule-a openhab 1459u a_inode 0,12 0 6848 [eventpoll]
java 696 836 OH-rule-a openhab 1460r FIFO 0,11 0t0 6807866 pipe
java 696 836 OH-rule-a openhab 1461w FIFO 0,11 0t0 6807866 pipe
java 696 836 OH-rule-a openhab 1462u a_inode 0,12 0 6848 [eventpoll]
java 696 836 OH-rule-a openhab 1463r FIFO 0,11 0t0 6807867 pipe
java 696 836 OH-rule-a openhab 1464w FIFO 0,11 0t0 6807867 pipe
java 696 836 OH-rule-a openhab 1465r FIFO 0,11 0t0 6807454 pipe
java 696 836 OH-rule-a openhab 1466w FIFO 0,11 0t0 6807454 pipe
java 696 836 OH-rule-a openhab 1467u a_inode 0,12 0 6848 [eventpoll]
…