Python execution takes too much time on new BBB image

[caladfelipe]

• Platform/operating system (i.e. Raspberry Pi with Raspbian operating system,
  Windows 32-bit, Windows 64-bit, Mac OSX 64-bit, etc.): Beaglebone Black Rev C, with image Debian 9.3 IoT 2018-03-05

• Python version (run python -version or python3 -version): (python) Python 2.7.13 or (python3) Python 3.5.3

• List the steps to reproduce the problem below (if possible attach code or commands
  to run):

I've updated the image of my BBB (previously used builtin image Debian 7.9 LXDE 2015-11-12) to Debian 9.3 IoT 2018-03-05, and I don't know why the execution of every python script take about 2 seconds to start running. I executed the following command: date; python test.py; date where test.py is:

import os
import logging
import logging.config
import random
from datetime import timedelta
import Adafruit_BBIO.GPIO as GPIO
import timeit

pin = 'P9_14'

GPIO.setup(pin, GPIO.OUT)

def setoutput():
  for x in range(1, 10):
    GPIO.output(pin, True)
    GPIO.output(pin, False)
    #run 5 times, 10 x 2 x 5 = 100 outputs

result = timeit.Timer(setoutput).timeit(5)
print('time to complete 100 sets = ', result)
GPIO.cleanup()

And the output is:

Tue Mar 20 04:07:38 UTC 2018
('time to complete 100 sets = ', 0.007684946060180664)
Tue Mar 20 04:07:40 UTC 2018

As you can see, it takes nearly 2 seconds to really execute the python code, situation which doesn't occur on the builtin image Debian 7.9. On that image executing python is nearly realtime, with no delays at all. I tried to optimize my scripts by a lot of ways but nothing seems to work.

Please help me to understand what is the issue on that image (it also happens on Debian 9.3 LXQT
2018-01-28) or what am I doing bad.

Useful information:

• cat /etc/dogcat: BeagleBoard.org Debian Image 2018-03-05
• cat /etc/debian_version: 9.3
• lscpu:

Architecture: armv7l
Byte Order: Little Endian
CPU(s): 1
On-line CPU(s) list: 0
Thread(s) per core: 1
Core(s) per socket: 1
Socket(s): 1
Model: 2
Model name: ARMv7 Processor rev 2 (v7l)
CPU max MHz: 1000.0000
CPU min MHz: 300.0000
BogoMIPS: 995.32
Flags: half thumb fastmult vfp edsp thumbee neon vfpv3 tls vfpd32

• sudo /opt/scripts/tools/version.sh:

git:/opt/scripts/:[e307a944e0be0610ff5296e0abe4ad31a6e70daa]
eeprom:[A335BNLT00C04417BBBK01BC]
model:[TI_AM335x_BeagleBone_Black]
dogtag:[BeagleBoard.org Debian Image 2018-03-05]
bootloader:[eMMC-(default)]:[/dev/mmcblk1]:[U-Boot 2018.01-00002-ge9ff418fb8]:[location: dd MBR]
kernel:[4.9.82-ti-r102]
nodejs:[v6.13.1]
uboot_overlay_options:[enable_uboot_overlays=1]
uboot_overlay_options:[enable_uboot_cape_universal=1]
pkg:[bb-cape-overlays]:[4.4.20180307.0-0rcnee0stretch+20180307]
pkg:[bb-wl18xx-firmware]:[1.20170829-0rcnee2stretch+20180104]
pkg:[firmware-ti-connectivity]:[20170823-1rcnee0~stretch+20170830]
groups:[debian : debian adm kmem dialout cdrom floppy audio dip video plugdev users systemd-journal i2c bluetooth netdev cloud9ide gpio pwm eqep admin spi tisdk weston-launch xenomai]
cmdline:[console=ttyO0,115200n8 bone_capemgr.uboot_capemgr_enabled=1 root=/dev/mmcblk1p1 ro rootfstype=ext4 rootwait coherent_pool=1M net.ifnames=0 quiet]
dmesg | grep pinctrl-single
[ 1.440948] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568
dmesg | grep gpio-of-helper
[ 1.448190] gpio-of-helper ocp:cape-universal: ready
END

• sudo python -c "import Adafruit_BBIO; print Adafruit_BBIO": <module 'Adafruit_BBIO' from '/usr/local/lib/python2.7/dist-packages/Adafruit_BBIO-1.0.10-py2.7-linux-armv7l.egg/Adafruit_BBIO/init.py'>
• sudo pip install --upgrade Adafruit_BBIO: Requirement already up-to-date: Adafruit_BBIO in /usr/local/lib/python2.7/dist-packages/Adafruit_BBIO-1.0.10-py2.7-linux-armv7l.egg
• strace -f -o strace.log python test.py: ('time to complete 100 sets = ', 0.06898188591003418)

Strace.log output

[pdp7]

thanks for opening this issue. i will investigate what causes the latency and followup with you.

[pdp7]

I can reproduce the delay that you are seeing:

debian@beaglebone:~$ uname -a
Linux beaglebone 4.16.0-rc2-bone3 #33 Wed Mar 21 21:51:01 CDT 2018 armv7l GNU/Linux

debian@beaglebone:~$ sudo python -c "import Adafruit_BBIO; print Adafruit_BBIO"
<module 'Adafruit_BBIO' from '/usr/local/lib/python2.7/dist-packages/Adafruit_BBIO-1.0.10-py2.7-linux-armv7l.egg/Adafruit_BBIO/__init__.pyc'>

debian@beaglebone:~$ date; sudo python ~/issue245-test.py; date
Wed Mar 28 04:16:32 UTC 2018
('time to complete 100 sets = ', 0.005589008331298828)
Wed Mar 28 04:16:34 UTC 2018

I will investigate further

[caladfelipe]

Great news!!! Hopefully you can figure out what is wrong out there...

Is there any way to flash to these BBB the image Debian 7.9 LXDE 2015-11-12 which is the "previously" image I quoted ?? Recently I bought a BBB on which I can not flash that image, and because of this is why I'm with the trouble of the delay. I tried to flash it using two SD cards (8GB and 32GB), and it failed. The BBB tries to start flashing but got stuck in some part because all the 4 leds remain on all the time and never turn off. In fact, the blinking process 1...2...3...4...3...2...1 never happens at all.

[pdp7]

I'm looking at the output of strace:
debian@beaglebone:~$ sudo strace -ttt -F -f -o /tmp/bbio.txt python ~/issue245-test.py

I don't see anything obvious. The main activity that I see is Python searching for dependencies in the file system. For example:

10219 1522210967.112222 open("/usr/lib/python2.7/sre_constants.so", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
10219 1522210967.112424 open("/usr/lib/python2.7/sre_constantsmodule.so", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
10219 1522210967.112596 open("/usr/lib/python2.7/sre_constants.py", O_RDONLY|O_LARGEFILE) = 7
10219 1522210967.112845 open("/usr/lib/python2.7/sre_constants.pyc", O_RDONLY|O_LARGEFILE) = 8
10219 1522210967.119792 open("/usr/lib/python2.7/_sysconfigdata.arm-linux-gnueabihf.so", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or dir
ectory)
10219 1522210967.120228 open("/usr/lib/python2.7/_sysconfigdata.so", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
10219 1522210967.120435 open("/usr/lib/python2.7/_sysconfigdatamodule.so", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
10219 1522210967.120615 open("/usr/lib/python2.7/_sysconfigdata.py", O_RDONLY|O_LARGEFILE) = 4
10219 1522210967.120881 open("/usr/lib/python2.7/_sysconfigdata.pyc", O_RDONLY|O_LARGEFILE) = 5

I'm not quite sure what optimizations are possible as this all seems like normal activity.

[pdp7]

@caladfelipe How are you trying to flash the image?

I would suggest that you download and install Etcher per the Getting Started guide:
https://beagleboard.org/getting-started#update

[caladfelipe]

I already tried Etcher to flash the image to the SD cards, edit uEnv.txt to uncomment the init flasher script, and finally insert the SD into the BBB to turn it on and get the image flashed on the device, but it didn't work. Occurs what I just told you:

The BBB tries to start flashing but got stuck in some part because all the 4 leds remain on all the time and never turn off. In fact, the blinking process 1...2...3...4...3...2...1 never happens at all.

[pdp7]

@RobertCNelson any suggestions for @caladfelipe? He wants to flash "Debian 7.9 LXDE 2015-11-12" onto the eMMC

[RobertCNelson]

@caladfelipe that old 7.9 image uses a 3.8.13 kernel, there are a couple reasons why it would fail.

It's best to plug in a usb-serial adapter into j1 to find out why it's stopping...

Regards,

[caladfelipe]

@RobertCNelson so I need to buy the usb-serial adapter. ¿Can you tell me please which of following cables allow me to connect to the BBB? https://www.adafruit.com/product/70 or https://www.amazon.com/Converter-Terminated-Galileo-BeagleBone-Minnowboard/dp/B06ZYPLFNB/ref=sr_1_1_sspa.

[pdp7]

@caladfelipe both those linked cables should work ok at they are 3.3V logic which is what the BeagleBone uses. I do personally use that Adafruit cable with my BeagleBone.

[pdp7]

@caladfelipe is this still an issue? thanks

[caladfelipe]

@pdp7 Yes, still having the same problem... :(

What else do you suggest me to do? Did you figure out something I can do to speed up python execution?

[pdp7]

@caladfelipe I'll run some benchmarks on the current Debian 9.x image and try to determine where that delay happens.

Have you tried using Python 3.x instead of Python 2.7?

[caladfelipe]

@pdp7 yes, the delay happens on both python versions

[pdp7]

@RobertCNelson Any thoughts on the best way to investigate this issue?

[pdp7]

@caladfelipe I have found on BeagleBoard.org Debian Image 2018-07-15 image that it takes less than 1 second for Python to run:

debian@beaglebone:~$ date; python test-245.py; date
Mon Aug 27 05:18:01 UTC 2018
('time to complete 100 sets = ', 0.00741887092590332)
Mon Aug 27 05:18:01 UTC 2018
debian@beaglebone:~$ python --version
Python 2.7.13

Please download the latest Debian Stretch image: bone-debian-9.5-iot-armhf-2018-08-23-4gb.img.xz and test if Python is still slow.

[pdp7]

@caladfelipe any feedback?

[caladfelipe]

@pdp7 let me run some tests with it.

Once I have some results I would let you know - Hope to tell you good news! :)

[caladfelipe]

@pdp7 just downloaded the image of the link, but it appears to be different than the one you mentioned. Even with the difference, I flashed the image on the BBB, but sadly the slowness still happening on python3.

root@beaglebone:/home/debian$ cat /etc/dogtag: BeagleBoard.org Debian Image 2018-08-23

root@beaglebone:/home/debian$ cat /etc/debian_version: 9.5

root@beaglebone:/home/debian$ python --version: Python 2.7.13

root@beaglebone:/home/debian$ python3 --version: Python 3.5.3

root@beaglebone:/home/debian$ date; python test.py; date

Thu Sep 6 23:21:26 -05 2018
('time to complete 100 sets = ', 0.007726192474365234)
Thu Sep 6 23:21:26 -05 2018

root@beaglebone:/home/debian$ date; python3 test.py; date

Thu Sep 6 23:21:37 -05 2018
time to complete 100 sets = 0.007196705999831465
Thu Sep 6 23:21:38 -05 2018

[pdp7]

@caladfelipe Are you saying the delay is 1 second?
start:

Thu Sep 6 23:21:37 -05 2018

stop:

Thu Sep 6 23:21:38 -05 2018

[pdp7]

@caladfelipe I notice that there is a 0.986 second difference.

Is that too much of a delay for your use case?

Python 2:

debian@beaglebone:~$ date +%H:%M:%S:%N; python2 test.py; date +%H:%M:%S:%N
06:38:41:286149043
('time to complete 100 sets = ', 0.007482051849365234)
06:38:41:825447650

Duration: 0.539298607

Python 3:

debian@beaglebone:~$ date +%H:%M:%S:%N; python3 test.py; date +%H:%M:%S:%N
06:38:43:524880141
time to complete 100 sets =  0.007496781996451318
06:38:44:547770922

Duration: 1.524880141

[caladfelipe]

@pdp7 the fact is that the real code I need to run has to import some packages, and the time spent during only the import takes too much time. The following code includes all the imports I have to make on my code:

`import time

print('Hello')
print(time.asctime())

import logging
import logging.config
import os
import psutil
import pymysql
import random
import requests
import signal
import simplejson as json
import subprocess
import time
import Adafruit_BBIO.ADC as ADC
import Adafruit_BBIO.GPIO as GPIO

from daemons.prefab import step
from datetime import timedelta
from git import Repo
from git.remote import FetchInfo
from git.exc import GitCommandError

print('World')
print(time.asctime())`

When you execute that code on a BBB, using the image you provided me, these are the results:

root@beaglebone:~$ date; python3 imp.py; date

Thu Nov 3 12:36:35 -05 2016
Hello
Thu Nov 3 12:36:35 2016
World
Thu Nov 3 12:36:38 2016
Thu Nov 3 12:36:39 -05 2016

It spends 3 seconds just in the import phase, which is a lot. If I run the same code in my laptop, it takes at most 1 second.

[pdp7]

@caladfelipe thanks for the update

@RobertCNelson any suggestions on how I can troubleshoot the increased latency to execute Python 3 code? thanks!

[RobertCNelson]

Couple Suggestions:

limit the number of imports
Faster microSD card
Stop comparing it directly against a laptop, as the the BBB is bandwidth and io limited... Unless that laptop is a p3 1Ghz with only 512mb of ram, and a crappy hd...

Regards,

[caladfelipe]

Thank you all the help! You're right @RobertCNelson , I can not compare it against a normal laptop...