Very slow processing on LISY1 (master mode)

[zacaj]

I'm working on some custom code for my Genie (system 1).  I've got a LISY1 with a RPi Zero W on it.  Apparently that's running mpf 0.51.1, per Ralf who makes the LISYs.  When I boot up the game in master mode, it starts up the attract mode as normal, but once I hit start everything is incredibly slow.  The best example of this is the top lanes (A thru D).  They should all turn on when a game starts, but when I hit start, there's a few second pause, and then A thru D (along with other lights) come on, but so slowly that I can see each lane turn on individually like a slow wave across the playfield.  Once all the lights have come on, there's another few second delay before the ball kicks out, and after that every switch has a large lag when I hit it.  

Is there any way to diagnose this?  I can view LISY's MPF log in real time via SSH and I can see the switch events come in, but there aren't any repeat events or anything that could be causing lag.   I'm not too familiar with the debug options or if there's any other way to diagnose the issue.  Ralf said that there was a 'lag bug' that was fixed in 0.50.21, so I'm not sure if this is maybe related.  I tried downgrading to the previous version of LISY which had 0.50.21 in case the bug had been reintroduced in 0.51.1 but it was the same.  

My latest code is available at https://github.com/zacaj/genie-mpf for reference...  

[Cole M]

I remember someone having a similar problem on a Pi last year and it turning out to be an IO bottle neck with the logging swamping the shared network USB interface.  Maybe try turning logging off?

[jabdoa]

The Text UI over ssh will definitely cause this on the RPi. But afaik LISY uses sane options to start MPF. Ralf probably knows more.

Jan

[zacaj]

What do you mean by the text ui? I'm just doing a tail on the log file, I
don't think anything else would happen over ssh

> --
> You received this message because you are subscribed to the Google Groups
> "MPF Users" group.
> To unsubscribe from this group and stop receiving emails from it, send an
> email to mpf-users+...@googlegroups.com.
> To post to this group, send email to mpf-...@googlegroups.com.
> Visit this group at https://groups.google.com/group/mpf-users.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/mpf-users/37cc4aeb-4e32-4c6f-a4c7-df17fb3a370a%40googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[jabdoa]

The Text UI is what MPF displays when run in foreground on the shell. You are not doing that. There has been a bug in 0.51 with the watchdog which slowed down everything but it should be fixed. Not sure how old your software image is.

Jan

[zacaj]

According to Ralf I'm on 0.51.1

[jabdoa]

0.51.1 should be fine. What is your poll_hz setting (http://docs.missionpinball.org/en/dev/config/lisy.html#poll-hz)? Maybe you need to reduce that on the RPi Zero. 50Hz would be a good setting probably.

Jan

[Lynn Crouch]

If you're using the latest release, my Solar Ride config files should be present on the image, and I think it has a usable polling setting you can reference. 

On Tue, Feb 12, 2019, 1:55 PM jabdoa <jan...@kantert.net wrote:

0.51.1 should be fine. What is your poll_hz setting (http://docs.missionpinball.org/en/dev/config/lisy.html#poll-hz)? Maybe you need to reduce that on the RPi Zero. 50Hz would be a good setting probably.

Jan

--

You received this message because you are subscribed to the Google Groups "MPF Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mpf-users+...@googlegroups.com.
To post to this group, send email to mpf-...@googlegroups.com.
Visit this group at https://groups.google.com/group/mpf-users.

To view this discussion on the web visit https://groups.google.com/d/msgid/mpf-users/0b2fdd17-1504-4b6a-af1a-b3ada53b5bd2%40googlegroups.com.

[zacaj]

My poll_hz was 100, matching the Solar Ride example config. I tried
setting it to 50 but it didn't help

[jabdoa]

Can you try a minimal config? Just to see if this is a general issue. If not start to re-add elements until the problem reappears. It's hard to find a slowdown generically when you don't know what causes it. You could add verbose logging or add debug: True to your devices. However, first find out which config causes it.

Jan

[zacaj]

 I removed everything but the lamps and am still having the issue.  Even attract mode, I notice, isn't running at a consistent speed.  

[jabdoa]

Can you post your machine somewhere? I would like to debug that.

Jan

[zacaj]

It's on my git repo.  Regular game is on master, my 'minimal' version is on the  minimal branch: https://github.com/zacaj/genie-mpf/tree/minimal

[jabdoa]

I looked into your game. This actually looks fine. Not sure why this slows down. How is the CPU utilization on the RPi? Can you login via serial and check that?

Jan

[Cole M]

I am having trouble with my shows running slow since upgrading to 52.  I've been blaming trouble with the MPF communication over the P-3ROC serial bus but maybe it is something else.  It would be interesting to know if your problem existed for MPF 0.50

[jabdoa]

LISY did not work properly in 0.50. Also, those shows are so basic that is must be something else. We will figure it out.

Jan

[zacaj]

I SSHed in and ran top, it's reporting about 30% CPU usage by pypy3 and around 5% by the mpfserver.  Nothing else using up much CPU.  Ram usage at 50%.  

[jabdoa]

That sounds good. Still does not explain why the lights lag so badly with nothing going on. Can you set "file_log: full" in your lisy section and post your log afterwards? That should show what MPF is sending to LISY and when it gets a response.

Jan

[zacaj]

I added file_log: full to the lisy: section, but I didn't see any additional logging in the file (/tmp/myMPFlog).  myMPFlog says the following at the top:

Machine : Command line arguments: {'no_load_cache': True, 'create_config_cache': False, 'bcp': False, 'configfile': ['config.yaml'], 'mpfconfigfile': '/opt/pypy3-v6.0.0-linux-armhf-raspbian/site-packages/mpf/mpfconfig.yaml', 'force_assets_load': False, 'logfile': '/tmp/myMPFlog', 'pause': False, 'production': False, 'text_ui': False, 'loglevel': 15, 'consoleloglevel': 20, 'force_platform': None, 'syslog_address': None, 'mc_file_name': None}

I added -v to the parameters and then got a ton of debug info.  I've attached that file.  Not sure if it's showing what you're looking for though.  

[jabdoa]

For some reason this is seriously slow:

2019-02-17 21:05:02,510 : DEBUG : lisy : Sending 41
2019-02-17 21:05:02,528 : DEBUG : lisy : Reading one byte
2019-02-17 21:05:02,566 : DEBUG : lisy : Sending 12 b'\x19'
2019-02-17 21:05:02,600 : DEBUG : lisy : Sending 11 b'\x1b'
2019-02-17 21:05:02,629 : DEBUG : lisy : Sending 12 b'\x13'
2019-02-17 21:05:02,866 : DEBUG : lisy : Sending 11 b'\x15'
2019-02-17 21:05:02,894 : DEBUG : lisy : Sending 12 b'\x07'
2019-02-17 21:05:02,918 : DEBUG : lisy : Sending 12 b'\x10'
2019-02-17 21:05:02,941 : DEBUG : lisy : Sending 11 b'\t'
2019-02-17 21:05:02,964 : DEBUG : lisy : Sending 11 b'\x0e'
2019-02-17 21:05:02,992 : DEBUG : lisy : Sending 12 b'\x0c'
2019-02-17 21:05:03,019 : DEBUG : lisy : Sending 11 b'\x11'
2019-02-17 21:05:03,041 : INFO : Machine : Starting the main run loop.
2019-02-17 21:05:03,079 : DEBUG : lisy : Sending 12 b'\x1a'
2019-02-17 21:05:03,131 : DEBUG : lisy : Sending 11 b'\x1c'
2019-02-17 21:05:03,162 : DEBUG : lisy : Sending 12 b'\x15'
2019-02-17 21:05:03,185 : DEBUG : lisy : Sending 11 b'\x14'
2019-02-17 21:05:03,212 : DEBUG : lisy : Sending 12 b'\t'
2019-02-17 21:05:03,235 : DEBUG : lisy : Sending 12 b'\x0e'
2019-02-17 21:05:03,261 : DEBUG : lisy : Sending 11 b'\x08'
2019-02-17 21:05:03,286 : DEBUG : lisy : Sending 11 b'\x0f'
2019-02-17 21:05:03,314 : DEBUG : lisy : Sending 12 b'\x11'
2019-02-17 21:05:03,452 : DEBUG : lisy : Sending 11 b'\x12'
2019-02-17 21:05:03,476 : DEBUG : lisy : Received 127

It takes 1s to read changed switches. Same for the watchdog to acknowledge. This is seriously slow. Not sure what is going on. Also there is about 30ms between two light commands. That does not look like your show. Later its around 10ms. Still a lot and probably visible. I guess that logging makes this slightly worse but still probably too slow for doing almost nothing.

This is really weird. I would expect MPF to burn 100% CPU for this to happen. Is anybody else using MPF on the RPi Zero? Maybe I need to get one to try it out.

Jan

[zacaj]

The logging didn't seem to have any noticeable affect on the speed of the attract mode.  Actually at one point while this was running, I think the attract mode actually sped up to the point where it was running faster than it should have been., but they may have just been my eyes.  There's definitely a variance in the speed the attract mode is running.  If you just sit there watching it it'll slow down or hang sometimes and then return to normalish speed.  

I think I have another RPi (not Zero) around somewhere, I'll try to dig it out and compare 

[jabdoa]

You could try two things:

a) Install uvloop (using pip)

b) Try python 3.6 instead of pypy3 (might help; not sure)

Can you run our benchmarks?

python3 -m unittest mpf.benchmarks.test_benchmark_light_shows

python3 -m unittest mpf.benchmarks.test_benchmark_switch_hits

I guess we should add a benchmark for actual end to end light tests.

Jan

[zacaj]

Tried with a RPi A, no difference.  

When I run your commands, I get an error:

Traceback (most recent call last):

  File "/usr/lib/python3.4/runpy.py", line 170, in _run_module_as_main

    "__main__", mod_spec)

  File "/usr/lib/python3.4/runpy.py", line 85, in _run_code

    exec(code, run_globals)

  File "/usr/lib/python3.4/unittest/__main__.py", line 18, in <module>

    main(module=None)

  File "/usr/lib/python3.4/unittest/main.py", line 92, in __init__

    self.parseArgs(argv)

  File "/usr/lib/python3.4/unittest/main.py", line 139, in parseArgs

    self.createTests()

  File "/usr/lib/python3.4/unittest/main.py", line 146, in createTests

    self.module)

  File "/usr/lib/python3.4/unittest/loader.py", line 146, in loadTestsFromNames

    suites = [self.loadTestsFromName(name, module) for name in names]

  File "/usr/lib/python3.4/unittest/loader.py", line 146, in <listcomp>

    suites = [self.loadTestsFromName(name, module) for name in names]

  File "/usr/lib/python3.4/unittest/loader.py", line 114, in loadTestsFromName

    parent, obj = obj, getattr(obj, part)

AttributeError: 'module' object has no attribute 'benchmarks'

I assume either I need to run this from a certain folder, or the benchmarks aren't installed?

Also, it seems that LISY is running mpf using pypy.  Should I also be running these benchmarks with pypy instead of python3 ?

[jabdoa]

Yeah you can try pypy3 instead of python3. Is that a RPI3 or a RPi1? The 1 should be similar to the Zero.

Jan

[zacaj]

RPi A+.  I guess it does seem similarly specced to the Zero...   Sadly I don't have any other RPis to compare

$ pypy3 -m unittest mpf.benchmarks.test_benchmark_light_shows

E

======================================================================

ERROR: benchmarks (unittest.loader._FailedTest)

----------------------------------------------------------------------

ImportError: Failed to import test module: benchmarks

Traceback (most recent call last):

  File "/opt/pypy3-v6.0.0-linux-armhf-raspbian/lib-python/3/unittest/loader.py", line 153, in loadTestsFromName

    module = __import__(module_name)

ImportError: No module named 'mpf.benchmarks'

----------------------------------------------------------------------

Ran 1 test in 0.012s

FAILED (errors=1)

[Lynn Crouch]

In my experiences thus far, the RPi 3 will run more smoothly, the Zero has a few bottlenecks somewhere, my own rig is also stuttery (pauses, then rushed to catch back up) in attract mode using a Zero, to say nothing of actually playing. Using a Pi 3 gives much better performance. You might also need an earlier model of Pi 3 (like an A); I had some trouble with images not booting correctly on a newer model.

--

You received this message because you are subscribed to the Google Groups "MPF Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mpf-users+...@googlegroups.com.
To post to this group, send email to mpf-...@googlegroups.com.
Visit this group at https://groups.google.com/group/mpf-users.

To view this discussion on the web visit https://groups.google.com/d/msgid/mpf-users/486e9462-fd29-4bdc-8639-1553dccbfa5b%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
Lynn http://lynnindenver.wordpress.com

[bontango]

Hello together,

sorry for jumping in so late ...

For the trouble with 'newer' PI3 ( PI3+) I'm working on a LISY Version 5.x, which will work with this model also.

Version 5.x is in beta testing for 'LISY35', but not fully tested with LISY1/LISY80 at the moment.

( latest status on LISY35 can be viewed here ( German only at the moment)

I will do some performance tests over the weekend with both LISY 4 and LISY 5 and different PI models as well

Please keep tuned

Ralf

[bontango]

Did some tests with mpf v.0.51, and raspbian stretch with PI-Zero, PI3B and PI3B+, details in appendix.

@zacaj: LISY4 comes with mpf 0.50 which do not have the benchmarks,

    you may want to try early LISY5: http://www.flipperkeller.de/lisy/LISY_Version_5_013.zip

It looks like the PI3 is 10 times faster for some tests than the PI Zero!

@jabdoa: I would have expected 3-4 times, but 10 times???

Also I had problems to install pypy3 with latest raspbian, Error message is:

   pypy3: error while loading shared libraries: libffi.so.5: cannot open shared object file: No such file or directory

Looks like version 5 is staticillay linked with pypy3 and raspbian stretch comes with libffi version 7

any hints how to get it working?

[jabdoa]

Thanks for running and sharing those benchmarks. I ran the same benchmarks on my PC (i5; 6th Gen). My numbers are roughly 10x the RPi3 Plus. Looks roughly like this to me: RPi Zero * 100 = RPi 3 * 10 = x86. pypy gives my another 7-8x gain on my machine.

Switch hits look reasonably fast for me. 300 hit/s in the worst case test on RPi Zero should be plenty for a machine. However, the show benchmark looks troubling. The one in 0.51 is still very optimistic since it does not benchmark the platform bits which lazily calculates the color for the lights. Adding that halves the result on my machine. Light shows are just too slow on the RPi Zero. I need to tune them at least 10x I guess.

Jan

[zacaj]

Do you think that these benchmarks explain my issues, even though my minimal version doesn't even use shows?  It sounded like my log had switches taking way longer than the benchmark shows...  I'll try the beta version and try to get my own benchmarks for comparison...

[jabdoa]

You are using light_player. That is probably a bit faster than shows but still quite slow overall it seems.

Jan