Offline update speed optimization

cifengfang · December 12, 2022, 11:28pm

Hi, I am building a lockbox to update containers on our device, which has three containers (weston-vivante, cog and custom app). It behaves as expected, but I recognized that it takes 6 mins to load cog image and 4 mins to load weston-vivannte image. I’m wondering whether there are ways to reduce the update time since we only want to update the app images/containers while keeping using the same weston-vivante and cog images/container.
Please see the below aktualizer logs for details. Thanks!

-- Logs begin at Thu 1970-01-01 00:00:06 UTC. --
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Certificate issuer: CN=ota-devices-CA
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Certificate valid from: Dec  2 23:45:47 2022 GMT until: Nov  8 23:45:47 2121 GMT
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: initializing...
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: using TCP port 8850.
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Offline Updates are enabled
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: starting thread.
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: listening to connections...
Dec 08 02:42:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete
Dec 08 02:52:40 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.
Dec 08 02:52:40 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: fetchMetaOffUpd() called with source_path: "/media/usb1/update"
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Current version for ECU ID: 918af54786776b6feed7cccb0d3b9626a9b28e22de5584fb6a249a4a572b865e is unknown
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: New updates found in Director metadata. Checking Image repo metadata...
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: 1 new update found in both Director and Image repo metadata.
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: UpdateCheckComplete, Result - Updates available
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Update available. Acquiring the update lock...
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Current version for ECU ID: 918af54786776b6feed7cccb0d3b9626a9b28e22de5584fb6a249a4a572b865e is unknown
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Image already fetched; skipping fetching
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: DownloadTargetComplete, Result - Success
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: AllDownloadsComplete, Result - Success
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Current version for ECU ID: 918af54786776b6feed7cccb0d3b9626a9b28e22de5584fb6a249a4a572b865e is unknown
Dec 08 02:53:10 colibri-imx8x-06787895 aktualizr-torizon[950]: Waiting for Secondaries to connect to start installation...
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: No update to install on Primary
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: InstallStarted
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: "/etc/sota/conf.d/100-offline-updates.toml"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: "/usr/lib/sota/conf.d/20-sota-device-cred.toml"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: "/usr/lib/sota/conf.d/30-rollback.toml"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: "/usr/lib/sota/conf.d/40-hardware-id.toml"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: "/usr/lib/sota/conf.d/50-secondaries.toml"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Reading config: "/usr/lib/sota/conf.d/60-polling-interval.toml"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Use existing SQL storage: "/var/sota/sql.db"
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: docker-compose file matches expected digest
Dec 08 02:53:12 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading metadata from tarball: /media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2.tar
Dec 08 02:55:50 colibri-imx8x-06787895 aktualizr-torizon[1391]: Loaded image: cifengfang/cxldnabit-release:digest_sha256_68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2
Dec 08 02:55:50 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading of "/media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2.tar" finished, code: 0, status: success
Dec 08 02:55:50 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading metadata from tarball: /media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf.tar
Dec 08 02:57:40 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.
Dec 08 03:01:41 colibri-imx8x-06787895 aktualizr-torizon[1422]: Loaded image: therndgroup/kiosk-mode-browser-vivante-cog:digest_sha256_29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf
Dec 08 03:01:42 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading of "/media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf.tar" finished, code: 0, status: success
Dec 08 03:01:42 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading metadata from tarball: /media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45.tar
Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[1477]: Loaded image: torizon/weston-vivante:digest_sha256_b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45
Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Loading of "/media/usb1/update/images/a6e85f5678c75cc4b691c2b7f001a23374c4e7fe603889e81451ad97ac7f64d5.images/b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45.tar" finished, code: 0, status: success
Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Updating containers via docker-compose
Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Running docker-compose down
Dec 08 03:05:04 colibri-imx8x-06787895 aktualizr-torizon[950]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml -p torizon down
Dec 08 03:05:10 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_web    ...
Dec 08 03:05:10 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_kiosk  ...
Dec 08 03:05:10 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_weston ...
Dec 08 03:05:12 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_web    ... done
Dec 08 03:05:13 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_kiosk  ... done
Dec 08 03:05:13 colibri-imx8x-06787895 aktualizr-torizon[1506]: Stopping cxldnabit_weston ... done
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_web    ...
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_kiosk  ...
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_weston ...
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_weston ... done
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_web    ... done
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[1506]: Removing cxldnabit_kiosk  ... done
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[950]: Running docker-compose up
Dec 08 03:05:14 colibri-imx8x-06787895 aktualizr-torizon[950]: Running command: /usr/bin/docker-compose --file /var/sota/storage/docker-compose/docker-compose.yml.tmp -p torizon up --detach --remove-orphans
Dec 08 03:05:18 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_weston ...
Dec 08 03:05:20 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_weston ... done
Dec 08 03:05:20 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_kiosk  ...
Dec 08 03:05:23 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_kiosk  ... done
Dec 08 03:05:23 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_web    ...
Dec 08 03:05:25 colibri-imx8x-06787895 aktualizr-torizon[1581]: Creating cxldnabit_web    ... done
Dec 08 03:05:26 colibri-imx8x-06787895 aktualizr-torizon[950]: Removing not used containers, networks and images
Dec 08 03:05:26 colibri-imx8x-06787895 aktualizr-torizon[950]: Running command: docker system prune -a --force
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: Deleted Images:
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: untagged: cifengfang/cxldnabit-release:digest_sha256_68377c13050f5fe2b20959534e5dc6639431e070bdbac875bfef1310705727f2
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: untagged: torizon/weston-vivante:2.5.1
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[1746]: Total reclaimed space: 0B
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: InstallTargetComplete, Result - Success
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: AllInstallsComplete, Result - OK
Dec 08 03:05:27 colibri-imx8x-06787895 aktualizr-torizon[950]: Update install completed. Releasing the update lock...
Dec 08 03:05:28 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete
Dec 08 03:05:31 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.
Dec 08 03:05:32 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete
Dec 08 03:07:40 colibri-imx8x-06787895 aktualizr-torizon[950]: PROXY: sending device data to Torizon OTA.
Dec 08 03:07:40 colibri-imx8x-06787895 aktualizr-torizon[950]: Event: SendDeviceDataComplete

jeremias.tx · December 13, 2022, 1:04am

Greetings @cifengfang,

Just to make sure I understand the setup, were the Cog and Weston-Vivante containers already present on the system? If yes, were these versions of the containers on the system the exact same versions that are in the Lockbox (besides the app container)?

If I understood correctly then, despite this it still took several minutes to update?

Best Regards,
Jeremias

cifengfang · December 13, 2022, 2:00am

Hi @jeremias.tx ,
Yes. The same version of cog and weston containers are already storaged on system, with the same digest key. Should I tag the images using the digest key as the update tool do so that it will recognize there are the same images?

jeremias.tx · December 13, 2022, 8:49pm

If you don’t mind could you perform a little test for me.

So for context when an offline update occurs and we load the container images from the Lockbox this is broken up into 2 distinct steps.

First we verify and validate the container image tarball for security reasons
Then we actually load the tarball and unpack the container image. Essentially we use docker load for this part.

With that information try this.

Start with your system as it was before you perform an offline update, so it has the initial versions of your containers.
Disable aktualizr.service or whatever such that the system does not perform an offline update automatically when you plug in your USB.
Now plug in your USB, make sure an offline update doesn’t automatically occur.
From the command-line run docker load < "path-to-container-tarball"
- You can see the paths for these tarballs in the aktualizr logs. There should be 1 tarball for reach container image included in the Lockbox
- Time how long this docker load process takes.

Basically I’m trying to see if the majority of the time taken during your offline update is happening on the validation part or the actual loading part.

Best Regards,
Jeremias

cifengfang · December 13, 2022, 10:15pm

Hi @jeremias.tx , here are the results for the test you suggested.

The loading time is much less than what I experienced during the lockbox update process. From the docker images output, you can see the weston and cog images are identical from the update tarball and original ones on the module.

jeremias.tx · December 13, 2022, 10:35pm

Interesting findings, so not even the longest docker load took more than a minute from what I can see. As you said this is drastically faster than the 4 and 6 minutes taken during the offline update process.

As a final test, I just recalled that the formatting of the USB drive used for offline updates can have a factor on speed. Most USB drives are formatted as FAT by default or something similar. However some testing has found that USB drives formatted EXT4 can increase performance and speed of the update.

Can you see if an EXT4 formatted USB drive helps to improve the speed of your offline update?

Best Regards,
Jeremias

cifengfang · December 14, 2022, 7:26pm

Hi @jeremias.tx. I have tried changing the USB drive file system to EXT4, but it doesn’t improve the result. As a summary, the custom app container takes 3mins, the cog takes 6 mins and the weston takes 3 mins to validate and load now. I saw a time consumption variation from the last test I did and I didn’t see the lockbox update valid and skipped the images that are the same.

jeremias.tx · December 14, 2022, 10:30pm

I saw a time consumption variation from the last test I did and I didn’t see the lockbox update valid and skipped the images that are the same.

Well due to security, every container image contained in the Lockbox goes through validation, even if it happens to be the same as an existing image already on the device. I mean technically we don’t know the container image is exactly the same until we are in the process of actually loading it.

Anyways with the docker load test you did it would appear that a majority of the time here is happening in the verification stage and not on the docker load stage. Though as I said we can’t really skip the verification stage without risking compromising something.

As a final test, if you happen to have multiple modules, does the offline update take this long on other Colibri i.MX8X modules as well? Just want to make sure there’s not issues with this specific module.

On my side I’ll see if we can do some testing with the speed of offline updates to see if what you’re experiencing is expected or not. In case we need to replicate your findings, are your container images here public for pulling?

EDIT: One more thing for our team here could you enable trace level logging for Aktualizr as documented here: Aktualizr - Modifying the Settings of Torizon Update Client | Toradex Developer Center

The amount of logs produced from this can be overwhelming so please capture it in a text file or something then share that here if you could.

Best Regards,
Jeremias

cifengfang · December 15, 2022, 5:07pm

Hi @jeremias.tx. Yes, all the images are publicly pullable. Please find the docker-compose file attached. Thanks. I will look into the Aktualizr logs for more details.
docker-compose.yml (2.5 KB)

jeremias.tx · December 15, 2022, 7:42pm

Thank you for the information, I’ll do my own testing and see if I can replicate your results. I’ll let you know if I discover anything or if I need more information from you.

Best Regards,
Jeremias

jeremias.tx · December 17, 2022, 12:51am

Here’s my after some testing using your containers. I focused on the loading of your weston-vivante and cog container since those were the containers that are not changing during the update.

As a reminder, I create a TorizonCore image with your containers pre-loaded then I attempted an offline update where the containers were not actually changing. Here is a snippet of the logs from my attempt:

Dec 17 00:39:33 colibri-imx8x-06750825 aktualizr-torizon[2368]: Loading metadata from tarball: /media/COSTCO_USB/update/images/004d1ad4a87eb74e7acae6c16ad153c50c64fa50759b702c3ea0b48ea9996522.images/29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf.tar
Dec 17 00:41:25 colibri-imx8x-06750825 aktualizr-torizon[2470]: Loaded image: cifengfang/kiosk-mode-browser-vivante-cog:digest_sha256_29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf
Dec 17 00:41:25 colibri-imx8x-06750825 aktualizr-torizon[2368]: Loading of "/media/COSTCO_USB/update/images/004d1ad4a87eb74e7acae6c16ad153c50c64fa50759b702c3ea0b48ea9996522.images/29659a376ad6647c8ee903cb2f2cf8a84f3890a1f68e95632e084e6723cbe2bf.tar" finished, code: 0, status: success
Dec 17 00:41:25 colibri-imx8x-06750825 aktualizr-torizon[2368]: Loading metadata from tarball: /media/COSTCO_USB/update/images/004d1ad4a87eb74e7acae6c16ad153c50c64fa50759b702c3ea0b48ea9996522.images/b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45.tar
Dec 17 00:42:29 colibri-imx8x-06750825 aktualizr-torizon[2506]: Loaded image: cifengfang/weston-vivante:digest_sha256_b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45
Dec 17 00:42:29 colibri-imx8x-06750825 aktualizr-torizon[2368]: Loading of "/media/COSTCO_USB/update/images/004d1ad4a87eb74e7acae6c16ad153c50c64fa50759b702c3ea0b48ea9996522.images/b39bd723e554a95522bd6774796d6af7cac7cf4960e1c142b9a6f45e62691f45.tar" finished, code: 0, status: success

As you can see I got very different results. The cog container image took ~2mins to load, while the weston-vivante took only ~1min. This leads me to think there’s another factor possibly at play here. On your setup there seems to be some kind of bottleneck limiting the speed of the update here when loading the images from the Lockbox.

Off the top of my head, as I said earlier maybe try a different Colibri i.MX8X module to eliminate the possibility of issues with that specific module. Also another thought, is maybe try another USB drive for the Lockbox, maybe the USB is what’s the limiting factor here.

In any case it doesn’t seem like I can replicate your results. I’m using the same module type (Colibri i.MX8X), and same container images as you so those probably aren’t the issue here.

Best Regards,
Jeremias