Time for an update?

General Discussions
18

I find these type of things interesting :), so I ran some tests for reference.

Mender client: 2.2.0
SD Card: Samsung EVO MB-MP32GA 32GB U1 Class 10 MicroSDHC Memory Card

Disk on device:

pi@raspberrypi:~ $ sudo fdisk -l /dev/mmcblk0
Disk /dev/mmcblk0: 29.8 GiB, 32010928128 bytes, 62521344 sectors
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0xdc6d2ff0

Device         Boot    Start      End  Sectors  Size Id Type
/dev/mmcblk0p1 *       24576   548863   524288  256M  c W95 FAT32 (LBA)
/dev/mmcblk0p2        548864 26476543 25927680 12.4G 83 Linux
/dev/mmcblk0p3      26476544 52404223 25927680 12.4G 83 Linux
/dev/mmcblk0p4      52404224 54501375  2097152    1G 83 Linux

Actual payload content (88 % free space)

pi@raspberrypi:~$ df -h
Filesystem      Size  Used Avail Use% Mounted on
/dev/root        13G  1.3G   11G  12% /

Raw Performacne test:

# Clear I/O cache
echo 3 | sudo tee /proc/sys/vm/drop_caches

# Write 1 GB of random data
time sudo dd if=/dev/urandom of=/dev/mmcblk0p3 bs=1M count=1024 oflag=dsync
1024+0 records in
1024+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 90.3429 s, 11.9 MB/s

Above should give is an good indication of the “raw” write performance of the SD
card and this is more or less how the Mender client writes the data. Mender client
of course needs to decompress the Artifact while writing which is CPU bound and
not I/O bound (well maybe memory I/O but this should not slow us down).

With the above information writing 12 GB of data in the best case should take: 18 minutes (90 seconds * 12)

Lets try it:

# Clear I/O cache
echo 3 | sudo tee /proc/sys/vm/drop_caches

pi@raspberrypi:~ $ time sudo mender -install 2020-02-05-raspbian-buster-lite-raspberrypi3-mender.mender
INFO[0000] Loaded configuration file: /var/lib/mender/mender.conf  module=config
INFO[0000] Loaded configuration file: /etc/mender/mender.conf  module=config
INFO[0000] Mender running on partition: /dev/mmcblk0p2   module=cli
INFO[0000] Start updating from local image file: [2020-02-05-raspbian-buster-lite-raspberrypi3-mender.mender]  module=standalone
Installing Artifact of size 465903616...
INFO[0000] no public key was provided for authenticating the artifact  module=installer
INFO[0000] opening device /dev/mmcblk0p3 for writing     module=block_device
INFO[0000] native sector size of block device /dev/mmcblk0p3 is 512, we will write in chunks of 1048576  module=block_device
................................   0% 1024 KiB
................................   0% 2048 KiB
................................   0% 3072 KiB
................................   0% 4096 KiB

< cut >

................................  99% 454656 KiB
..........INFO[1724] 0 bytes remaining to be written               module=limited_writer
INFO[1724] The optimized block-device writer wrote a total of 12661 frames, where 3072 frames did need to be rewritten  module=block_device
INFO[1724] Wrote 13274972160/13274972160 bytes to the inactive partition  module=dual_rootfs_device
                       100% 454984 KiB
INFO[1725] Enabling partition with new image installed to be a boot candidate: 3  module=dual_rootfs_device
Use -commit to update, or -rollback to roll back the update.
At least one payload requested a reboot of the device it updated.

real    28m45.767s
user    18m44.459s
sys 0m53.113s

Pretty much the same result that you are sharing so far, in both time and block written/skipped.

I can also confirm that I get similar results running the same update multiple times. Probably something in Raspbian that alters the filesystem image enough for the optimizations not to provide much effect here, e.g the Linux kernel argument fsck.repair=yes could be causing this.

What the time output also tells us is that almost 10 minutes are being wasted on waiting, because the user and sys times gives us the numbers in CPU time spent in user/kernel mode and they do not add up to the real time.

As I am reading the Mender Artifact in the local filesystem I suspected that it is actually “choking” the SDIO bus because we have three operations running on it:

  1. The .mender file is being read from the local file system
  2. The Mender client will read ahead blocks in the inactive partition
  3. The Mender client will write blocks to the inactive partition

So I tried moving my .mender file to a USB flash drive to avoid 1.

# Clear I/O cache
echo 3 | sudo tee /proc/sys/vm/drop_caches

pi@raspberrypi:~ $ time sudo mender -install /mnt/2020-02-05-raspbian-buster-lite-raspberrypi3-mender.mender 
INFO[0000] Loaded configuration file: /var/lib/mender/mender.conf 
WARN[0000] No server URL(s) specified in mender configuration. 
WARN[0000] Server entry 1 has no associated server URL. 
INFO[0000] Mender running on partition: /dev/mmcblk0p2  
INFO[0000] Start updating from local image file: [/mnt/2020-02-05-raspbian-buster-lite-raspberrypi3-mender.mender] 
Installing Artifact of size 465903616...
INFO[0000] No public key was provided for authenticating the artifact 
INFO[0000] Opening device "/dev/mmcblk0p3" for writing  
INFO[0000] Native sector size of block device /dev/mmcblk0p3 is 512 bytes. Mender will write in chunks of 1048576 bytes 
................................   0% 1024 KiB
................................   0% 2048 KiB

< CUT >

................................  99% 454656 KiB
..........INFO[1465] All bytes were successfully written to the new partition 
INFO[1465] The optimized block-device writer wrote a total of 12661 frames, where 566 frames did need to be rewritten (i.e., skipped) 
INFO[1466] Wrote 13274972160/13274972160 bytes to the inactive partition 
                       100% 454984 KiB
INFO[1466] Enabling partition with new image installed to be a boot candidate: 3 
Use -commit to update, or -rollback to roll back the update.
At least one payload requested a reboot of the device it updated.

real    24m26.881s
user    18m31.913s
sys 0m41.828s

Improvement but still ~6 minutes unaccounted for. Overhead of decompression? Overhead of golang? Overhead of reading and comparing blocks? Probably combination of all of them

So the short answer to you question (which was already said :)), what you are seeing is expected behavior of the 2.2.0 client in this environment (Raspbian)

2 Likes