Lego Ev3Dev Python slow
interrupts from infraredsensor in mode=IR-REMOTE
Finally, I was able to narrow down the problem and find some workarounds
usingwhile true ; do { { date; cat /proc/interrupts ; } >>int.txt ; sleep 10 ; } done we see how the interrupt counters increase. The major difference before and after the python script
interrupts/sec
boot run prox
53: 0 5240 53 cp_intc 53 Edge ttyS1
56: 1 642 1 cp_intc 56 Edge spi_davinci.1
There are 3 columns with measurements
- boot: after boot
- run: after python was run, which is using Infraredsensor and leaving it in mode=IR-REMOTE
- prox: after setting Infraredsensor to mode=IR-PROX (using a further python script)
Conclusion
- setting the Infraredsensor to mode IR-PROX reduces the interrupts to sensible rate, without a relevant performance impact
- the infraredsensor in mode=IR-REMOTE is a slow device, I do not understand, that it uses nearly 6000 interrupts/second
- however, this problem occurs with Infraredsensor in Input1, in Input4 there is now slowup. The mindstorms user guide read, that input4 is the default for infraredsensor. I didn't find a restriction.
Is this a bug in ev3dev, or a hardware problem in my brick?
other processes 14.12.18
As mentioned before, we have kworker/* using over 30% cpu after the first run. And I still would like to get an answer what they are doing, or how I can find it out. I only used python and I'm not aware, that I fed any work to kworkers.
You can see that, in points 1 - 5 below - during the python runs top was not active here. It Seems that idle going back from 90% to 30% explains the nearly 4 times longer runtime.
However, running top during python, shows a different picture. Maximal CPU usage for Python decreased from 70% to 40% only, furthermore, IO-Wait decreased from a peak of 6% to permanently 0.0. But if you look at Time+ in top, you see that the total cpu consumption of Python doubled (see points 6 and 7 below)
logs ⇒ Inf:dir.php?f=legoEv3/errordocs/181214slowPython
- top after boot
top - 07:25:26 up 13 min, 1 user, load average: 0.00, 0.24, 0.39 Tasks: 70 total, 1 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 4.1 us, 3.7 sy, 0.0 ni, 92.2 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 57640 total, 2096 free, 21824 used, 33720 buff/cache KiB Swap: 98300 total, 95740 free, 2560 used. 31944 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 88 root -51 0 0 0 0 S 5.1 0.0 0:44.76 irq/249-ev3-tac 1063 robot 20 0 8048 2896 2504 R 4.2 5.0 0:01.11 top 67 root -51 0 0 0 0 S 3.8 0.0 0:31.28 irq/247-ti-ads7 490 root 20 0 51192 8328 6488 S 1.1 14.4 0:16.99 brickman 7 root 20 0 0 0 0 S 0.6 0.0 0:03.60 ksoftirqd/0 - run my python program init ⇒ 7.5 sec
- top some time later
top - 07:31:59 up 20 min, 1 user, load average: 0.56, 0.46, 0.43 Tasks: 72 total, 2 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 21.6 us, 47.0 sy, 0.0 ni, 31.4 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 57640 total, 4316 free, 21644 used, 31680 buff/cache KiB Swap: 98300 total, 94972 free, 3328 used. 32180 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 53 root 20 0 0 0 0 R 32.7 0.0 0:35.56 kworker/u2:1 1117 robot 20 0 8048 2812 2420 R 7.8 4.9 0:08.44 top 88 root -51 0 0 0 0 S 6.8 0.0 1:08.73 irq/249-ev3-tac 490 root 20 0 51192 5184 3372 S 6.3 9.0 0:24.92 brickman 67 root -51 0 0 0 0 S 5.0 0.0 0:48.05 irq/247-ti-ads7 1103 root 20 0 0 0 0 I 4.8 0.0 0:25.28 kworker/u2:4 13 root 20 0 0 0 0 I 0.5 0.0 0:06.44 kworker/0:1
- run my python program init ⇒ 27 sec
- top some time later
top - 07:35:36 up 23 min, 1 user, load average: 0.94, 0.72, 0.55 Tasks: 71 total, 1 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 13.3 us, 51.0 sy, 0.0 ni, 35.7 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 57640 total, 5656 free, 21476 used, 30508 buff/cache KiB Swap: 98300 total, 94716 free, 3584 used. 32316 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1158 root 20 0 0 0 0 I 32.8 0.0 0:12.01 kworker/u2:0 1174 robot 20 0 8048 2928 2536 R 8.4 5.1 0:02.96 top 88 root -51 0 0 0 0 S 6.8 0.0 1:23.36 irq/249-ev3-tac 67 root -51 0 0 0 0 S 4.6 0.0 0:58.14 irq/247-ti-ads7 394 root 20 0 0 0 0 I 2.3 0.0 0:50.22 kworker/u2:3 53 root 20 0 0 0 0 I 1.6 0.0 0:56.10 kworker/u2:1 490 root 20 0 51192 5104 3324 S 1.6 8.9 0:30.17 brickman 49 root 20 0 0 0 0 S 0.5 0.0 0:06.10 spi0
- first python after boot during top active - last to screens, with python active
top - 08:24:40 up 7 min, 1 user, load average: 0.43, 0.85, 0.59 Tasks: 73 total, 2 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 85.6 us, 13.0 sy, 0.0 ni, 0.0 id, 1.1 wa, 0.0 hi, 0.3 si, 0.0 st KiB Mem : 57640 total, 1300 free, 25480 used, 30860 buff/cache KiB Swap: 98300 total, 94972 free, 3328 used. 28360 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1005 robot 20 0 22740 9340 5040 R 70.0 16.2 0:09.18 python3 916 robot 20 0 8044 2864 2468 R 6.9 5.0 0:11.74 top 88 root -51 0 0 0 0 S 6.7 0.0 0:25.82 irq/249-ev3-tac 67 root -51 0 0 0 0 S 4.2 0.0 0:17.73 irq/247-ti-ads7 20 root 20 0 0 0 0 S 1.9 0.0 0:01.93 kswapd0 491 root 20 0 51196 5036 3192 S 1.4 8.7 0:11.75 brickman 57 root 20 0 0 0 0 S 0.8 0.0 0:03.35 mmcqd/0 top - 08:24:45 up 7 min, 1 user, load average: 0.48, 0.85, 0.59 Tasks: 73 total, 2 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 51.2 us, 44.4 sy, 0.0 ni, 4.2 id, 0.2 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 57640 total, 1620 free, 26120 used, 29900 buff/cache KiB Swap: 98300 total, 94716 free, 3584 used. 27724 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1005 robot 20 0 56980 9820 5052 R 43.9 17.0 0:10.76 python3 916 robot 20 0 8044 2864 2468 R 10.3 5.0 0:12.11 top 5 root 20 0 0 0 0 I 8.1 0.0 0:00.62 kworker/u2:0 88 root -51 0 0 0 0 S 7.8 0.0 0:26.10 irq/249-ev3-tac 53 root 20 0 0 0 0 I 5.3 0.0 0:00.81 kworker/u2:1 67 root -51 0 0 0 0 S 5.0 0.0 0:17.91 irq/247-ti-ads7 347 root 20 0 0 0 0 I 3.1 0.0 0:00.65 kworker/u2:3 20 root 20 0 0 0 0 S 2.2 0.0 0:02.01 kswapd0 491 root 20 0 51196 5128 3288 S 2.2 8.9 0:11.83 brickman 895 robot 20 0 11524 4120 3404 S 1.4 7.1 0:00.69 sshd 8 root 20 0 0 0 0 I 0.8 0.0 0:02.23 rcu_preempt - second python after boot during top active - last to screens, with python active
top - 08:28:17 up 11 min, 1 user, load average: 1.70, 1.12, 0.74 Tasks: 72 total, 3 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 55.6 us, 44.4 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 57640 total, 1544 free, 25668 used, 30428 buff/cache KiB Swap: 98300 total, 94716 free, 3584 used. 28176 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1066 robot 20 0 23188 9804 5176 R 40.3 17.0 0:20.40 python3 347 root 20 0 0 0 0 R 17.7 0.0 0:22.94 kworker/u2:3 5 root 20 0 0 0 0 I 17.3 0.0 0:33.51 kworker/u2:0 916 robot 20 0 8044 2864 2468 R 9.2 5.0 0:36.30 top 88 root -51 0 0 0 0 S 6.6 0.0 0:39.51 irq/249-ev3-tac 67 root -51 0 0 0 0 S 4.7 0.0 0:27.85 irq/247-ti-ads7 491 root 20 0 51196 4948 3180 S 1.9 8.6 0:16.08 brickman 8 root 20 0 0 0 0 I 0.6 0.0 0:03.15 rcu_preempt top - 08:28:22 up 11 min, 1 user, load average: 2.20, 1.23, 0.78 Tasks: 72 total, 3 running, 46 sleeping, 0 stopped, 0 zombie %Cpu(s): 49.1 us, 41.5 sy, 0.0 ni, 9.2 id, 0.0 wa, 0.0 hi, 0.2 si, 0.0 st KiB Mem : 57640 total, 1704 free, 26076 used, 29860 buff/cache KiB Swap: 98300 total, 94716 free, 3584 used. 27768 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1066 robot 20 0 56860 9968 5196 R 34.5 17.3 0:22.03 python3 5 root 20 0 0 0 0 I 9.9 0.0 0:33.98 kworker/u2:0 347 root 20 0 0 0 0 I 9.5 0.0 0:23.39 kworker/u2:3 916 robot 20 0 8044 2864 2468 R 9.3 5.0 0:36.74 top 53 root 20 0 0 0 0 R 7.6 0.0 0:24.49 kworker/u2:1 88 root -51 0 0 0 0 S 6.8 0.0 0:39.83 irq/249-ev3-tac 67 root -51 0 0 0 0 S 4.7 0.0 0:28.07 irq/247-ti-ads7 491 root 20 0 51196 4944 3180 S 4.0 8.6 0:16.27 brickman 895 robot 20 0 11524 4120 3404 S 1.3 7.1 0:00.79 sshd 980 root 20 0 0 0 0 I 0.8 0.0 0:01.44 kworker/0:0
Infos form 6.12.18
Here are the desired infos. I simplified the script a bit, so its a bit faster.
- The first run after boot is more than 3 times faster than the following one (still tedious, but not catastrophic).
- Python module cache seems to work
- top shows that python runs the whole time at +-40% CPU, furthermore there are two processes kworker*/u* that together use also nearly 40%cpu, even a long time after python has finished
- Infos from 6.12.18
- ev3dev-sysinfo -m
<!-- Copy everything between these lines --> **System info (from `ev3dev-sysinfo`)** ``` Image file: ev3dev-stretch-ev3-generic-2018-08-06 Kernel version: 4.14.80-ev3dev-2.3.1-ev3 Brickman: 0.10.0 BogoMIPS: 148.88 Board: board0 BOARD_INFO_HW_REV=7 BOARD_INFO_MODEL=LEGO MINDSTORMS EV3 BOARD_INFO_ROM_REV=6 BOARD_INFO_SERIAL_NUM=001653535C31 BOARD_INFO_TYPE=main ``` <!-- Copy everything between these lines -->
- dpkg-query -l python3-ev3dev*
Desired=Unknown/Install/Remove/Purge/Hold | Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend |/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad) ||/ Name Version Architecture Description +++-==========================-==================-==================-========================================================= ii python3-ev3dev 1.2.0 all Python language bindings for ev3dev ii python3-ev3dev2 2.0.0~beta2 all Python language bindings for ev3dev
- python programm ir1.py
#!/usr/bin/env python3 from datetime import datetime print(str(datetime.now()), "00 import datetime", __file__) import time import threading from queue import Queue, Empty import sys print(str(datetime.now()), "01 import sys", __file__) #from modmod import * #print(str(datetime.now()), "02 import modmod", __file__) from ev3dev2.motor import * print(str(datetime.now()), "03 import motor", __file__) from ev3dev2.led import Leds from ev3dev2.button import * from ev3dev2.sensor.lego import InfraredSensor #from ev3dev2._platform.ev3 import * print(str(datetime.now()), "10 imported all", __file__) # print('EVDEV_DEVICE_NAME', EVDEV_DEVICE_NAME) # for name, mod in sys.modules.items(): # print(name, '-->', mod) class IRButThr(threading.Thread): """ thread ev3 brick buttons """ def __init__(self): threading.Thread.__init__(self) self.ir = InfraredSensor() self.ir.mode = InfraredSensor.MODE_IR_REMOTE self.info() def info(self): print("InfraredSensor " + self.ir.address, "\n\tmodes=" + repr(self.ir.modes), "\n\t_BUTTONS=" + repr(self.ir._BUTTONS), "\n\t commands=" + repr(self.ir.commands)) def run(self): self.running = True; print(str(datetime.now()), "20 run begin", __file__) if self.ir.mode == self.ir.MODE_IR_REMOTE: buttons = None while self.running: n = self.ir.buttons_pressed(1) if n != self.buttons: print(str(datetime.now()) + " ir buttons ch1 " + repr(n)) self.buttons = n time.sleep(0.001) elif self.ir.mode == self.ir.MODE_IR_PROX: self.prox = None while self.running: n = self.ir.proximity if n != self.prox: print(str(datetime.now()) + " ir proximity ch1 " + repr(n)) self.prox = n time.sleep(0.001) elif self.ir.mode == self.ir.MODE_IR_SEEK: self.heaDis = None while self.running: n = self.ir.heading_and_distance(1) if n != self.heaDis: print(str(datetime.now()) + " ir Heading Distance ch1 " + repr(n)) self.heaDis = n #pMod() break time.sleep(0.001) print(str(datetime.now()), "12 after class", __file__) print("sys.version", sys.version) print(datetime.now(), "platform", get_current_platform()) # print("devices", repr(evdev.list_devices())) # print("dev 2", repr([evdev.InputDevice(fn).name for fn in evdev.list_devices()])) it = IRButThr() it.ir.mode = InfraredSensor.MODE_IR_SEEK it.run() print(str(datetime.now()), "19 end", __file__) - start bash
echo "$0 1 begin $(date)" { echo "$0 2 begin $(date)" ~/ir1.py echo "$0 3 end $(date)" } > ~/o echo "$0 4 end $(date)" - first run after boot 13 seconds
- terminal
robot@ev3dev:~$ date;./ir;date Thu Dec 6 07:36:26 UTC 2018 ./ir 1 begin Thu Dec 6 07:36:26 UTC 2018 ./ir 4 end Thu Dec 6 07:36:39 UTC 2018 Thu Dec 6 07:36:39 UTC 2018
- output file
./ir 2 begin Thu Dec 6 07:36:26 UTC 2018 2018-12-06 07:36:30.259489 00 import datetime /home/robot/ir1.py 2018-12-06 07:36:32.038558 01 import sys /home/robot/ir1.py 2018-12-06 07:36:33.201292 03 import motor /home/robot/ir1.py 2018-12-06 07:36:38.618301 10 imported all /home/robot/ir1.py 2018-12-06 07:36:38.622371 12 after class /home/robot/ir1.py sys.version 3.5.3 (default, Sep 27 2018, 17:25:39) [GCC 6.3.0 20170516] 2018-12-06 07:36:38.624242 platform ev3 InfraredSensor ev3-ports:in1 modes=['IR-PROX', 'IR-SEEK', 'IR-REMOTE', 'IR-REM-A', 'IR-S-ALT', 'IR-CAL'] _BUTTONS=('top_left', 'bottom_left', 'top_right', 'bottom_right', 'beacon') commands=[] 2018-12-06 07:36:38.814454 20 run begin /home/robot/ir1.py 2018-12-06 07:36:38.869329 ir Heading Distance ch1 (0, 0) 2018-12-06 07:36:38.870529 19 end /home/robot/ir1.py ./ir 3 end Thu Dec 6 07:36:39 UTC 2018
- terminal
- second run after boot 47 secs
- third run after boot 45 secs
- terminal
robot@ev3dev:~$ date;./ir;date Thu Dec 6 07:43:19 UTC 2018 ./ir 1 begin Thu Dec 6 07:43:19 UTC 2018 ./ir 4 end Thu Dec 6 07:44:04 UTC 2018 Thu Dec 6 07:44:04 UTC 2018
- output
./ir 2 begin Thu Dec 6 07:43:19 UTC 2018 2018-12-06 07:43:31.049553 00 import datetime /home/robot/ir1.py 2018-12-06 07:43:37.800533 01 import sys /home/robot/ir1.py 2018-12-06 07:43:42.356409 03 import motor /home/robot/ir1.py 2018-12-06 07:44:03.174098 10 imported all /home/robot/ir1.py 2018-12-06 07:44:03.188040 12 after class /home/robot/ir1.py sys.version 3.5.3 (default, Sep 27 2018, 17:25:39) [GCC 6.3.0 20170516] 2018-12-06 07:44:03.199930 platform ev3 InfraredSensor ev3-ports:in1 modes=['IR-PROX', 'IR-SEEK', 'IR-REMOTE', 'IR-REM-A', 'IR-S-ALT', 'IR-CAL'] _BUTTONS=('top_left', 'bottom_left', 'top_right', 'bottom_right', 'beacon') commands=[] 2018-12-06 07:44:03.515667 20 run begin /home/robot/ir1.py 2018-12-06 07:44:03.549832 ir Heading Distance ch1 (0, None) 2018-12-06 07:44:03.553457 19 end /home/robot/ir1.py ./ir 3 end Thu Dec 6 07:44:04 UTC 2018
- terminal