Login

fiorello · 11-29-2020, 03:07 PM

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!

**Tim Curtis** · 11-29-2020, 03:58 PM

20201129 000019 worker: Integrity check (warning: worker.php)

fiorello · 11-29-2020, 04:21 PM

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!

**Tim Curtis** · 11-29-2020, 05:12 PM

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.

fiorello · 11-30-2020, 08:56 AM

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?

**Tim Curtis** · 11-30-2020, 12:33 PM

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.

fiorello · 12-01-2020, 06:08 PM

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?

**TheOldPresbyope**

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

fiorello · 12-06-2020, 04:27 PM

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?

**TheOldPresbyope** · 12-06-2020, 06:18 PM

@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

Login
Username:
Password:	Lost Password?
	Remember me