Thank you for your donation!


Cloudsmith graciously provides open-source package management and distribution for our project.


Problem: Autoplay after start
#1
Hi

For my application it is essential that moOde plays the last played item after powering-up / booting.

To test the correct funtionality I set up a test environment including two identiacl DUTs:

moOde release = 6.7.1 2020-07-22                                                                                                                              
Platform      = Pi-Zero W 512MB v1.1                                                                                                                          
Audio device  = HiFiBerry DAC+                                                                                                                                
Interface     = I2S                                                                                                                                           
Auto-shuffle  = Off                                                                                                                                           
Autoplay      = On                                                                                                                                            

The test environment includes a dedicated hardware and software (separate microcontroller), which periodically cycles the following sequence on both DUTs:

1) Power up DUT
2) Wait until moOde on DUT plays item (check play signal on HiFiBerry DAC+)
3) Initiate shutdown on DUT
4) Wait 30s
5) Power down DUT
6) Wait 10s

The testing runs for hours without any problem. However, several times the testing failed:

- Issue occured on both DUTs simultanously in the same test cyclus (!)
- The faulty test cyclus was the first one started in a day (!),
  i.e. after the date changed while the testing runs

Below are the log files of a failed test cyclus.

/var/log/moode.log:
Code:
20201129 000016 worker: -- Start
20201129 000016 worker: Successfully daemonized
20201129 000019 worker: Integrity check (warning: worker.php)
20201129 000019 worker: Integrity check (passed with warnings)
20201129 000019 worker: Session loaded
20201129 000019 worker: Debug logging (off)
20201129 000019 worker: Device raw: (0:sndrpihifiberry|1:empty|2:empty|3:empty
20201129 000019 worker: Device i2s: (HiFiBerry DAC+)
20201129 000019 worker: Device mpd: (0:HiFiBerry DAC+)
20201129 000019 worker: Device ses: (0|HiFiBerry DAC+|Digital|0%)
20201129 000021 worker: ALSA Digital volume set to (0%)
20201129 000021 worker: -- System
20201129 000027 worker: Host     (moode)
20201129 000028 worker: moOde    (6.7.1 2020-07-22)
20201129 000028 worker: RaspiOS  (10.4)
20201129 000028 worker: Kernel   (5.4.51+ #1325)
20201129 000028 worker: Platform (Pi-Zero W 512MB v1.1)
20201129 000028 worker: ARM arch (armv6l, 32-bit kernel)
20201129 000028 worker: MPD ver  (0.21.24)
20201129 000028 worker: CPU gov  (ondemand)
20201129 000028 worker: USB boot not available
20201129 000058 worker: File system not expanded yet
20201129 000058 worker: HDMI port on
20201129 000102 worker: File check (OK)
20201129 000102 worker: -- Network
20201129 000103 worker: eth0 does not exist
20201129 000103 worker: eth0 address not assigned
20201129 000103 worker: wlan0 exists
20201129 000103 worker: wifi country (CH)
20201129 000103 worker: wlan0 trying SSID (ASUS_RT-AC68U_24)
20201129 000104 worker: IP addr (192.168.0.184)
20201129 000105 worker: Netmask (255.255.255.0)
20201129 000105 worker: Gateway (192.168.0.1)
20201129 000106 worker: Pri DNS (62.2.24.158)
20201129 000106 worker: Domain  (home)
20201129 000107 worker: -- Audio
20201129 000110 worker: MPD conf updated
20201129 000112 worker: ALSA outputs unmuted
20201129 000112 worker: ALSA card number (0)
20201129 000112 worker: Audio output (HiFiBerry DAC+)
20201129 000114 worker: Audio formats (S16_LE, S24_LE, S32_LE)
20201129 000114 worker: ALSA mixer name (Digital)
20201129 000114 worker: MPD volume control (hardware)
20201129 000115 worker: Hdwr volume controller exists
20201129 000115 worker: Max ALSA volume (100%)
20201129 000115 worker: Reset renderer active flags
20201129 000115 worker: -- MPD
20201129 000116 worker: MPD started
20201129 000119 worker: MPD connection refused
20201129 000119 worker: Configure MPD outputs
20201129 000120 worker: 
20201129 000120 worker: 
20201129 000120 worker: 
20201129 000120 worker: 
20201129 000120 worker: 
20201129 000120 worker: 
20201129 000120 worker: 
20201129 000120 worker: MPD crossfade (off)
20201129 000120 worker: -- Feature availability
20201129 000120 worker: Source select (available)
20201129 000120 worker: Source select (source: MPD)
20201129 000120 worker: Source select (output: HiFiBerry DAC+)
20201129 000120 worker: Bluetooth (available)
20201129 000120 worker: Airplay renderer (available)
20201129 000120 worker: Spotify renderer (available)
20201129 000120 worker: Squeezelite renderer (available)
20201129 000120 worker: UPnP renderer (available)
20201129 000120 worker: DLNA server (available)
20201129 000120 worker: UPnP browser (available)
20201129 000120 worker: Audio scrobbler (available)
20201129 000120 worker: GPIO button handler (available)
20201129 000120 worker: GPIO button handler (started)
20201129 000120 worker: -- Music sources
20201129 000121 worker: USB sources (none attached)
20201129 000121 worker: NAS and UPnP sources (none configured)
20201129 000121 worker: -- Miscellaneous
20201129 000122 worker: Rotary encoder on (100 2 10 23 24)
20201129 000122 worker: USB volume knob (Off)
20201129 000123 worker: Shellinabox SSH started
20201129 000123 worker: USB auto-mounter (udisks-glue)
20201129 000126 worker: LED0 (On)
20201129 000126 worker: LED1 (sysclass does not exist)
20201129 000126 worker: Saved MPD vol level (0)
20201129 000126 worker: Preamp volume level (0)
20201129 000126 worker: MPD volume level (60) restored
20201129 000127 worker: ALSA Digital volume (87%)
20201129 000127 worker: Auto-play (On)
20201129 000127 worker: Auto-playing id ()
20201129 000127 worker: Maintenance interval (3 hrs)
20201129 000127 worker: Screen saver activation (Never)
20201129 000127 worker: Session permissions (OK)
20201129 000129 worker: Watchdog started
20201129 000129 worker: Ready

/var/log/mpd/log:
Code:
Nov 26 19:48 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 19:55 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 20:00 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 20:01 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 20:04 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 20:05 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"

(cut away entries to save space in this thread)

Nov 26 23:52 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 23:53 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 23:55 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 23:56 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 23:58 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 26 23:59 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 00:01 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 00:02 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 00:04 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 00:05 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 00:07 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 00:08 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"

(cut away entries to save space in this thread)

Nov 27 23:45 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:47 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:48 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:50 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:51 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:53 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:54 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:56 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:57 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 27 23:59 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:00 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:02 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:03 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:05 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:06 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:08 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:09 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 00:11 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"

(cut away entries to save space in this thread)

Nov 28 23:33 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:34 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:36 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:37 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:40 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:42 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:43 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:45 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:47 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:49 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:50 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:52 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:54 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:56 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:57 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"
Nov 28 23:59 : player: played "SDCARD/Dr. Feelgood-Case History-10-Milk And Alcohol-Rock-192kbps.mp3"

/var/log/syslog:
Code:
Nov 29 00:01:31 moode rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="289" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Nov 29 00:01:31 moode rsyslogd:  [origin software="rsyslogd" swVersion="8.1901.0" x-pid="289" x-info="https://www.rsyslog.com"] rsyslogd was HUPed
Nov 29 00:01:32 moode nmbd[395]: [2020/11/29 00:01:32.499160,  0] ../source3/nmbd/nmbd_workgroupdb.c:276(dump_workgroups)
Nov 29 00:01:32 moode nmbd[395]:   dump_workgroups()
Nov 29 00:01:32 moode nmbd[395]:    dump workgroup on subnet   192.168.0.184: netmask=  255.255.255.0:
Nov 29 00:01:32 moode nmbd[395]:   #011WORKGROUP(1) current master browser = UNKNOWN
Nov 29 00:01:32 moode nmbd[395]:   #011#011MOODE 40809a03 (moOde SMB Server)
Nov 29 00:01:33 moode systemd[1]: logrotate.service: Succeeded.
Nov 29 00:01:33 moode systemd[1]: Started Rotate log files.
Nov 29 00:01:33 moode systemd[1]: Startup finished in 3.777s (kernel) + 1min 26.298s (userspace) = 1min 30.076s.
Nov 29 00:15:04 moode systemd[1]: Starting Cleanup of Temporary Directories...
Nov 29 00:15:04 moode systemd[1]: systemd-tmpfiles-clean.service: Succeeded.
Nov 29 00:15:04 moode systemd[1]: Started Cleanup of Temporary Directories.
Nov 29 00:23:13 moode systemd[1]: Created slice User Slice of UID 1000.
Nov 29 00:23:13 moode systemd[1]: Starting User Runtime Directory /run/user/1000...
Nov 29 00:23:13 moode systemd[1]: Started User Runtime Directory /run/user/1000.
Nov 29 00:23:13 moode systemd[1]: Starting User Manager for UID 1000...
Nov 29 00:23:14 moode systemd[5160]: Listening on GnuPG cryptographic agent and passphrase cache (access for web browsers).
Nov 29 00:23:14 moode systemd[5160]: Reached target Paths.
Nov 29 00:23:14 moode systemd[5160]: Listening on GnuPG cryptographic agent and passphrase cache.
Nov 29 00:23:14 moode systemd[5160]: Listening on GnuPG cryptographic agent and passphrase cache (restricted).
Nov 29 00:23:14 moode systemd[5160]: Reached target Timers.
Nov 29 00:23:14 moode systemd[5160]: Listening on GnuPG network certificate management daemon.
Nov 29 00:23:14 moode systemd[5160]: Listening on GnuPG cryptographic agent (ssh-agent emulation).
Nov 29 00:23:14 moode systemd[5160]: Starting D-Bus User Message Bus Socket.
Nov 29 00:23:14 moode systemd[5160]: Listening on D-Bus User Message Bus Socket.
Nov 29 00:23:14 moode systemd[5160]: Reached target Sockets.
Nov 29 00:23:14 moode systemd[5160]: Reached target Basic System.
Nov 29 00:23:14 moode systemd[1]: Started User Manager for UID 1000.
Nov 29 00:23:14 moode systemd[5160]: Reached target Default.
Nov 29 00:23:14 moode systemd[5160]: Startup finished in 753ms.
Nov 29 00:23:14 moode systemd[1]: Started Session c1 of user pi.

So, the issue seems to be caused by MPD connection refused. However, there seems to be some conjunction between this issue and the time of starting worker.php and / or last shutdown before starting worker.php. As mentioned, the issue occurred exclusively (several times) only when worker.php was started the first time of a new day.

Do you have any suggestion? Maybe some conjunction with the maintenance routine in moOde (truncated logs)?

Thanks!
Reply
#2
20201129 000019 worker: Integrity check (warning: worker.php)
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Reply
#3
Hi Tim

Thanks for your answer!

I modified worker.php by adding a single command which starts a script. This is used (by setting a GPIO port) to inform my underlaying microcontroller that the raspi has booted and moOde is ready. Modified snipped of my worker.php:

Code:
// Auto-configure if indicated
// NOTE: This is done near the end of startup because autoConfig() uses the wpa_passphrase utility which requires
// sufficient kernel entropy in order to generate the PSK. If there is not enough entropy, wpa_passphrase returns
// the input password instead of a PSK.
if (file_exists('/boot/moodecfg.txt')) {
    sysCmd('truncate ' . AUTOCFG_LOG . ' --size 0');

    autoConfig('/boot/moodecfg.txt');

    sysCmd('sync');
    autoCfgLog('autocfg: System restarted');
    sysCmd('reboot');
}

// Script to indicate the PIC that the raspi has booted and is running
sysCmd('sudo bash /var/local/www/commandw/gpio_set.sh');

// Start watchdog monitor
sysCmd('/var/www/command/watchdog.sh > /dev/null 2>&1 &');
workerLog('worker: Watchdog started');

//
workerLog('worker: Ready');
$result = sdbquery("UPDATE cfg_system SET value='1' WHERE param='wrkready'", $dbh);
//

//
// BEGIN WORKER JOB LOOP
//

My script "gpio_set.sh" is as follows:
Code:
#!/bin/bash
#
# Set GPIO11 to indicate the PIC that the raspi has booted and is running.
echo 11 > /sys/class/gpio/export
echo out > /sys/class/gpio/gpio11/direction
echo 1 > /sys/class/gpio/gpio11/value

So, I don't expect any issues by this... Or am I wrong?

Thanks!
Reply
#4
The log entries below indicate some sort of performance issue on the Pi. MPD start is initiated and ~3 secs later no connection can be established to MPD, prolly cos it has not completed its startup yet for some reason. This is a rare because MPD should start and accept connections almost instantly.

20201129 000116 worker: MPD started
20201129 000119 worker: MPD connection refused

During the time period after MPD start is initiated moOde tries up to 5 times with a .5 sec sleep between each try to open a connection to MPD.
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Reply
#5
Yea, I realized this also. Normally (if autoplay works correctly) this is done quicker:
Code:
20201126 014300 worker: MPD started
20201126 014301 worker: MPD accepting connections

Probably I could go ahead and increment the loop condition in function openMpdSock() from 6 to let's say 30, but I prefer to solve the problem if any possible then having a workaround. Do you have any idea what prolongs MPD's startup time under certain conditions? It seems to be kind of deterministic condition, see test results above...

In the release notes for moOde 6.5.2 is mentioned:
- FIX: Start up logic for auto play and auto-shuffle

Do you see any context between this fix and my actual issue?
Reply
#6
The challenge with problems like this is that the issue is intermittent which makes it difficult to troubleshoot or repro.

IIRC there is a systemd utility that can be used to create a detailed log of system startup and since MPD is started by systemd it might show something. Have a look at the file "/lib/systemd/system/mpd.service" and also "systemctl status mpd". There's also dmesg and syslog that might show something.

It could also be something like a slow SDCard or just the slow single-core Zero. Maybe try swapping in one of the quad-core Pi's like a 3A+ or 3B+, a new SDCard, etc.
Enjoy the Music!
moodeaudio.org | Mastodon Feed | GitHub
Reply
#7
So I will try to narrow down this issue by collecting more debug information. IMO the issue is not hardware related, the intermittent occurrence and other indications refer to a software problem.

However, I noticed an interresting point in the moode-logfiles of the two DUTs which where started simultaneously for testing:

/var/log/moode.log (snipped), DUT #1:
Code:
20201129 000028 worker: CPU gov  (ondemand)
20201129 000028 worker: USB boot not available
20201129 000058 worker: File system not expanded yet
20201129 000058 worker: HDMI port on
20201129 000102 worker: File check (OK)

/var/log/moode.log (snipped), DUT #2:
Code:
20201129 000035 worker: USB boot not available
20201129 000036 worker: File system not expanded yet
20201129 000105 worker: HDMI port on
20201129 000109 worker: File check (OK)
20201129 000109 worker: -- Network

So, both DUTs have some mystifying delay in the worker startup sequence, but after different operations.

DUT#1:
20201129 000028 worker: USB boot not available
20201129 000058 worker: File system not expanded yet

DUT#2:
20201129 000036 worker: File system not expanded yet
20201129 000105 worker: HDMI port on

Any idea what could be the cause for these delays? Same cause as for the timeout to open a connection to MPD?
Reply
#8
I think the command Tim was thinking of is systemd-analyze.

Here's the output for two different options running systemd-analyze on one of my moOde players (moode-r700-rc5) on an RPi-3B+ with a local (official Raspberry Pi) display and with the triggerhappy daemon enabled:


Code:
pi@RC5LD:~ $ systemd-analyze blame
        12.143s dhcpcd.service
         4.348s dev-sda2.device
         1.859s rc-local.service
         1.833s raspi-config.service
         1.825s nmbd.service
         1.472s man-db.service
         1.442s nginx.service
          694ms smbd.service
          658ms keyboard-setup.service
          604ms systemd-udev-trigger.service
          583ms systemd-fsck@dev-disk-by\x2dpartuuid-2fed7fee\x2d01.service
          575ms networking.service
          550ms systemd-timesyncd.service
          496ms systemd-logind.service
          456ms wpa_supplicant.service
          448ms avahi-daemon.service
          427ms winbind.service
          371ms user@1000.service
          344ms rsyslog.service
          328ms systemd-journald.service
          301ms systemd-fsck-root.service
          288ms polkit.service
          287ms systemd-udevd.service

pi@RC5LD:~ $ systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

multi-user.target @22.505s
└─smbd.service @21.807s +694ms
 └─winbind.service @21.373s +427ms
   └─nmbd.service @19.541s +1.825s
     └─network-online.target @19.534s
       └─network.target @19.522s
         └─dhcpcd.service @7.374s +12.143s
           └─basic.target @7.181s
             └─sockets.target @7.177s
               └─triggerhappy.socket @7.174s
                 └─sysinit.target @7.160s
                   └─systemd-timesyncd.service @6.605s +550ms
                     └─systemd-tmpfiles-setup.service @6.415s +161ms
                       └─local-fs.target @6.406s
                         └─boot.mount @6.325s +75ms
                           └─systemd-fsck@dev-disk-by\x2dpartuuid-2fed7fee\x2d01.service @5.730s +583ms
                             └─dev-disk-by\x2dpartuuid-2fed7fee\x2d01.device @5.307s

You can consult the man page for information about this output.

Regards,
Kent
Reply
#9
Thanks for clarification!

Situation here is as follows (moOde 6.7.1 2020-07-22, Pi-Zero W 512MB v1.1, Sandisk microSDHC, 16GB, U1, UHS-I):

Code:
pi@moode:~ $ systemd-analyze blame
         10.638s dhcpcd.service
         10.577s dev-mmcblk0p2.device
          4.295s rc-local.service
          3.463s systemd-timesyncd.service
          3.314s nmbd.service
          3.264s keyboard-setup.service
          3.174s smbd.service
          3.079s networking.service
          2.936s systemd-udev-trigger.service
          2.868s nginx.service
          2.529s raspi-config.service
          2.528s winbind.service
          2.515s systemd-logind.service
          2.495s php7.3-fpm.service
          1.907s rng-tools.service
          1.698s sysstat.service
          1.698s systemd-journald.service
          1.677s systemd-rfkill.service
          1.654s avahi-daemon.service
          1.637s systemd-fsck@dev-disk-by\x2dpartuuid-2fed7fee\x2d01.service
          1.566s ssh.service
          1.411s alsa-restore.service
          1.283s systemd-update-utmp.service
          1.169s wpa_supplicant.service
          1.132s systemd-fsck-root.service
          1.065s rsyslog.service
           897ms user@1000.service
           880ms systemd-remount-fs.service
           868ms systemd-tmpfiles-setup.service
           856ms run-rpc_pipefs.mount
           805ms dev-mqueue.mount
           794ms kmod-static-nodes.service
           704ms systemd-sysctl.service
           695ms systemd-modules-load.service
           652ms systemd-user-sessions.service
           637ms sys-kernel-debug.mount
           609ms systemd-journal-flush.service
           608ms systemd-sysusers.service
           522ms rpi-eeprom-update.service
           499ms systemd-random-seed.service
           449ms fake-hwclock.service
           441ms rpcbind.service
           402ms udisks.service
           393ms systemd-udevd.service
           311ms systemd-update-utmp-runlevel.service
           258ms nfs-config.service
           218ms console-setup.service
           182ms systemd-tmpfiles-setup-dev.service
           161ms user-runtime-dir@1000.service
           161ms boot.mount
           132ms sys-kernel-config.mount
            96ms ifupdown-pre.service
pi@moode:~ $ systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.
                                                                                                                                                                               
multi-user.target @41.725s
+-smbd.service @38.528s +3.174s
  +-winbind.service @35.918s +2.528s
    +-nmbd.service @32.533s +3.314s
      +-network-online.target @32.228s
        +-network.target @32.181s
          +-dhcpcd.service @21.521s +10.638s
            +-basic.target @21.084s
              +-sockets.target @21.074s
                +-avahi-daemon.socket @21.048s
                  +-sysinit.target @20.985s
                    +-systemd-timesyncd.service @17.495s +3.463s
                      +-systemd-tmpfiles-setup.service @16.525s +868ms
                        +-local-fs.target @16.485s
                          +-boot.mount @16.289s +161ms
                            +-systemd-fsck@dev-disk-by\x2dpartuuid-2fed7fee\x2d01.service @14.605s +1.637s
                              +-dev-disk-by\x2dpartuuid-2fed7fee\x2d01.device @12.610s
pi@moode:~ 

So, what is the conclusion? Pi-Zero W not suited as moOde player?
Reply
#10
@fiorello 

I won't pretend I have a clear understanding of the issue at hand but certainly the RPiZeroW has been satisfactory for a number of users who aren't exercising moOde's more advanced features.

The following may be irrelevant, but in terms of RaspiOS startup, I looked at the output of systemd-analyze blame and systemd-analyze run on several of my devices (times probably vary somewhat from boot to boot but I didn't pursue):

1. RPi3A
time to initialize the root partition service (dev-mmcblk02.device): <3s
reached multi-user.target after 30+s in userspace
startup finished in 41+s


2. RPi3B+
time to initialize the root partition service (dev-sd2.device, on a USB2 Thumbdrive): 4+s
reached multi-user.target after 22+s in userspace
startup finished in 29+s


3. RPi4B
time to initialize the root partition service (dev-mmcblk02.device): <3s
reached multi-user.target after 19s in userspace
startup finished in 21s

4. RPiZeroW
time to initialize the root partition service (dev-mmcblk02.device): ca 12s
reached multi-user.target after 50s in userspace
startup finished in 60s

Clearly everything takes longer with the Zero.

I didn't look at the subsequent startup of moOde processes.

Regards,
Kent
Reply


Forum Jump: