performance issue?

[johngo7470]

Compiled/running the latest Bluelog (downloaded yesterday) on Raspberry Pi Stretch (4.19.66-v7+).

When I run bluelog, it seems to be using up resources, or apparently blocking resources. "top" doesn't show any significant CPU usage, but just hitting the return character a few times in another window, shows that something is being seriously slowed down. I wasn't even able to start a new putty session - seems it timed out, waiting to connect.

Has anyone else seen this?

[MS3FGX]

Interesting, first I've heard of this problem. Have you checked to see if it's dumping any errors to syslog? Is Bluelog actually working and seeing devices, or does it seem to have locked up as well?

[johngo7470]

journalctl looks ok:

Sep 26 12:33:18 raspi sudo[1500]:       pi : TTY=pts/1 ; PWD=/home/pi/Downloads/Bluelog ; USER=root ; COMMAND=/bin/rm log2.log
Sep 26 12:33:18 raspi sudo[1500]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Sep 26 12:33:18 raspi sudo[1500]: pam_unix(sudo:session): session closed for user root
Sep 26 12:33:23 raspi bluelog[1508]: Init OK!
Sep 26 12:34:13 raspi bluelog[1508]: Shutdown OK.

...as does syslog, auth.log, daemon.log, user.log, and messages... (at most, only show the init Ok and shutdown ok)

When Bluelog is running, there is 3-10 seconds of delay between when I enter a command or hit the return key a few times (in another window), and when there is any kind of response.

Directly running sudo hciscan lescan, does not produce any delay response.

Bluelog did list a device last night, but currently, I'm at work, and nothing is turned on at home (where my RPi is).

pi@raspi:~/Downloads/Bluelog $ ./bluelog -o /home/pi/Downloads/Bluelog/log2.log -v
Bluelog (v1.1.3-dev) by MS3FGX
---------------------------
Autodetecting device...OK
Opening output file: /home/pi/Downloads/Bluelog/log2.log...OK
Writing PID file: /tmp/bluelog.pid...OK
Scan started at [09/26/19 12:50:10] on B8:27:EB:CA:15:CF
Hit Ctrl+C to end scan.

Top:

top - 13:20:17 up 6 min,  3 users,  load average: 0.00, 0.06, 0.04
Tasks: 144 total,   1 running,  95 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.3 us,  0.1 sy,  0.0 ni, 99.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :   944244 total,   524144 free,   186544 used,   233556 buff/cache
KiB Swap:   102396 total,   102396 free,        0 used.   686392 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  786 root      20   0  206560  52544  30512 S   0.6  5.6   0:02.73 Xorg
  940 pi        20   0    8228   3284   2720 R   0.6  0.3   0:01.29 top
  828 lightdm   20   0  185220  68928  23916 S   0.5  7.3   0:03.64 pi-greeter
  352 root      20   0   34528   4316   3976 S   0.2  0.5   0:00.95 adb
   33 root      20   0       0      0      0 I   0.1  0.0   0:00.04 kworker/2:1-eve
   69 root     -51   0       0      0      0 S   0.1  0.0   0:00.13 irq/86-mmc1
  117 root      20   0       0      0      0 I   0.1  0.0   0:00.11 kworker/u8:2-ev
  988 root      20   0       0      0      0 I   0.1  0.0   0:00.03 kworker/u8:3-ev
 1023 pi        20   0    3972    568    480 S   0.1  0.1   0:00.01 bluelog
    1 root      20   0   28180   6144   4920 S   0.0  0.7   0:02.72 systemd
    2 root      20   0       0      0      0 S   0.0  0.0   0:00.00 kthreadd
    3 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 rcu_gp

JohnG

[MS3FGX]

Does the same thing happen when you start Bluelog as a non-interactive daemon (the -d option) as when it's being run in the foreground? Have you tried using -s to log only to syslog, and not write a log file?

Basically, we can see that Bluelog isn't doing much with the CPU/RAM, but I'm wondering if somehow it's tying up system I/O which is why you're getting general input lag.

[MS3FGX]

Also, did you mention which Pi version this is on? I don't have a Pi 4 yet, but I've got pretty much all of the previous versions. Maybe I can install Stretch to see if I can recreate the issue.

[johngo7470]

Does the same thing happen when you start Bluelog as a non-interactive daemon (the -d option)
as when it's being run in the foreground? Have you tried using -s to log only to syslog, and not
write a log file?

Yep :( (enabled with both -d and -s, but still created highly delayed responses)

Basically, we can see that Bluelog isn't doing much with the CPU/RAM, but I'm wondering if
somehow it's tying up system I/O which is why you're getting general input lag.

Yes, the behavior does seem more consistent with an I/O issue...

pi@raspi:~/Downloads/Bluelog $ cat /etc/os-release
PRETTY_NAME="Raspbian GNU/Linux 9 (stretch)"
NAME="Raspbian GNU/Linux"
VERSION_ID="9"
VERSION="9 (stretch)"
VERSION_CODENAME=stretch
ID=raspbian
ID_LIKE=debian
HOME_URL="http://www.raspbian.org/"
SUPPORT_URL="http://www.raspbian.org/RaspbianForums"
BUG_REPORT_URL="http://www.raspbian.org/RaspbianBugs"

Hardware : BCM2835
Revision : a02082 (Pi3B)
Serial : 000000004160bf65

pi@raspi:~/Downloads/Bluelog $ uname -a
Linux raspi 4.19.66-v7+ #1253 SMP Thu Aug 15 11:49:46 BST 2019 armv7l GNU/Linux

[johngo7470]

I installed Bluelog on my RPi4... it didn't show the "slow down" behavior, but it did seem to trip up communications in some way. After I started it, I wasn't able to start another ssh session to RPi, nor even ping it from my laptop.

Though on the RPi, I was able to ping my laptop. Then, communication started working again, as I was able to ping/ssh to the RPi, from my laptop.

After starting Bluelog, I did see a couple bluetooth mac addresses, but then address reporting stopped (I have a BTLE motions sensor that sent an advertisement). I then issued a bluelog -k (in another window), and the process appeared to gracefully exit.

pi@raspberrypi:~/Downloads/Bluelog $ ./bluelog -o /home/pi/Downloads/Bluelog/log.log -v
Bluelog (v1.1.3-dev) by  MS3FGX
---------------------------
Autodetecting device...OK
Opening output file: /home/pi/Downloads/Bluelog/log.log...OK
Writing PID file: /tmp/bluelog.pid...OK
Scan started at [09/27/19 18:46:52] on DC:A6:32:02:78:67
Hit Ctrl+C to end scan.
[09/27/19 18:46:56] B8:27:EB:CA:15:CF,IGNORED,0x480000
[09/27/19 18:46:56] A4:E4:B8:5A:CF:F3,IGNORED,0x7a020c

Closing files and freeing memory...Done!
pi@raspberrypi:~/Downloads/Bluelog $

No indications of an issue in syslog:

Sep 27 18:42:08 raspberrypi PackageKit: daemon start
Sep 27 18:42:08 raspberrypi dbus-daemon[377]: [system] Successfully activated service 'org.freedesktop.PackageKit'
Sep 27 18:42:08 raspberrypi systemd[1]: Started PackageKit Daemon.
Sep 27 18:46:52 raspberrypi bluelog: Init OK!
Sep 27 18:48:53 raspberrypi PackageKit: daemon quit
Sep 27 18:48:53 raspberrypi systemd[1]: packagekit.service: Main process exited, code=killed, status=15/TERM
Sep 27 18:48:53 raspberrypi systemd[1]: packagekit.service: Succeeded.
Sep 27 18:50:20 raspberrypi systemd[1]: Started Session c12 of user pi.
Sep 27 19:09:20 raspberrypi bluelog: Shutdown OK.
Sep 27 19:10:03 raspberrypi systemd[1]: proc-sys-fs-binfmt_misc.automount: Got automount request for /proc/sys/fs/binfmt_misc, triggered by 14022 (find)
Sep 27 19:10:03 raspberrypi systemd[1]: Mounting Arbitrary Executable File Formats File System...
Sep 27 19:10:03 raspberrypi systemd[1]: Mounted Arbitrary Executable File Formats File System.
pi@raspberrypi:/var/log $

JohnG

[johngo7470]

Sorry - strike that bit about connectivity issue to RPi4 - I forgot to update the IP in putty...

Seems to run fine without I/O impact on RPi4. Possibly an issue with other contents on my RPi3.

One question... should Bluelog display LE devices? Seems to only show non-LE...

[MS3FGX]

Yeah, I wasn't able to replicate on the Pi 3 so I wonder what else is going on there. Would love to know what the problem is, but hard to say with so many variables. There any notable pieces of software you remember installing on the Pi 3 that could be conflicting?

As for BLE, unfortunately Bluelog only works with "Classic" Bluetooth devices. When I started this project, BLE hadn't even been formally adopted, and it was still another few years before the hardware actually became common enough to test against.

I've looked at trying to add BLE support, but BlueZ is kind of a mess and it's not nearly as simple as you might think. BLE scanning is a whole different thing than Classic scanning, and requires root permissions. As it stands, Bluelog won't even run if you're root so as not to open up any potential security issues with the number of files it can read/write. It's certainly not impossible, but would require a substantial rewrite that honestly I'm not sure is worth it anymore.

If you need support for both Classic and BLE, then BlueHydra from Pwnie Express is probably your best bet.

https://github.com/pwnieexpress/blue_hydra

[johngo7470]

There any notable pieces of software you remember installing on the Pi 3 that could be conflicting?

Unfortunately, no. It would take a while to try to figure it out, but in learning BLE isn't currently available, sadly, looks like this will be "one of those things".

In my particular case, I want to pick up BLE advertisements (from cheap IR motion sensors). My pref would be for this function to be native to RPi, but worst case, I can use an Arduino to pick up the advertisements and relay them to RPi. It's not the cleanest solution, but it should do what I need.

Thank you for Bluelog - I still have another project that it might come in handy for.