# Delayed output from mender show-artifact **URL:** \ **Category:** General Discussions\ **Tags:** mender\ **Created:** [May 23, 2023, 1:42pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856 "2023-05-23T13:42:17Z")\ **Posts on this page:** 16\ **Page:** 1
**Author:** ![antony](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/antony/32/1422_2.png) [@antony](https://hub.mender.io/u/antony)\ **Post date:** [May 23, 2023, 1:42pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/1 "2023-05-23T13:42:17Z")
Hi all, We are using mender client version 3.5.0 (from [mender.io](http://mender.io) Ubuntu repository) on an ARM64 system and are noticing a change in behaviour compared to version 3.1.0 that we were previously using. We have noticed that with version 3.5.0 the `show-artifact` option takes about 5s to respond, where previously the response was immediate. There are 2 quite noticeable pauses when using the `-l info` logging level: ```auto # mender -l info show-artifact |& cat - time="2023-05-23T13:38:20Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf" time="2023-05-23T13:38:20Z" level=info msg="'UpdateControlMapExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 2*UpdatePollIntervalSeconds" time="2023-05-23T13:38:20Z" level=info msg="'UpdateControlMapBootExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 600 seconds" time="2023-05-23T13:38:22Z" level=info msg="Mender running on partition: /dev/mmcblk0p2" time="2023-05-23T13:38:25Z" level=info msg="Mender running on partition: /dev/mmcblk0p2" build_20230516_502 ``` As you can see there are two 2 second pauses before responding. Running `strace` shows at least one of them is caused by a `futex()` system call. It seems that the mender client internal locking is causing these delays. Is this a regression or an intended change ? Kind regards, Antony. ---
**Author:** ![wisse-cp](https://avatars.discourse-cdn.com/v4/letter/w/e36b37/32.png) [@wisse-cp](https://hub.mender.io/u/wisse-cp)\ **Post date:** [June 26, 2023, 3:31pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/2 "2023-06-26T15:31:28Z")
We noticed the same issue, it would take a fraction of a second before and now takes between 10 and 15 seconds. This is significantly increasing our startup times as our application wants to know the current version. ---
**Author:** ![clementp](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/clementp/32/1392_2.png) [@clementp](https://hub.mender.io/u/clementp)\ **Post date:** [July 12, 2023, 3:22pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/3 "2023-07-12T15:22:03Z")
Hi, I bump to Kirkstone recently and got also the same issue. It seems that a new feature doHandleBootstrapArtifact() is taking time and the database is never created ```auto ~# mender --log-level debug show-artifact [2023-07-12 13:45:38] DEBU[0000]/conf/config.go:283 conf.readConfigFile() Reading Mender configuration from file /var/lib/mender/mender.conf [2023-07-12 13:45:38] INFO[0000]/conf/config.go:276 conf.loadConfigFile() Loaded configuration file: /var/lib/mender/mender.conf [2023-07-12 13:45:38] DEBU[0000]/conf/config.go:283 conf.readConfigFile() Reading Mender configuration from file /etc/mender/mender.conf [2023-07-12 13:45:38] INFO[0000]/conf/config.go:276 conf.loadConfigFile() Loaded configuration file: /etc/mender/mender.conf [2023-07-12 13:45:38] DEBU[0000]/conf/config.go:169 conf.LoadConfig() Loaded 2 configuration file(s) [2023-07-12 13:45:38] INFO[0000]/conf/config.go:236 conf.checkConfigDefaults() 'UpdateControlMapExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 2*UpdatePollIntervalSeconds [2023-07-12 13:45:38] INFO[0000]/conf/config.go:243 conf.checkConfigDefaults() 'UpdateControlMapBootExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 600 seconds [2023-07-12 13:45:38] DEBU[0000]/conf/config.go:178 conf.LoadConfig() Loaded configuration = &conf.MenderConfig{MenderConfigFromFile:conf.MenderConfigFromFile{ArtifactVerifyKey:"", ArtifactVerifyKeys:[]string{"/etc/mender/artifact-verify-key.pem"}, HttpsClient:client.HttpsClient{Certificate:"", Key:"", SSLEngine:""}, Security:clie nt.Security{AuthPrivateKey:"", SSLEngine:""}, Connectivity:client.Connectivity{DisableKeepAlive:false, IdleConnTimeoutSeconds:0}, RootfsPartA:"/dev/mmcblk0p2", RootfsPartB:"/dev/mmcblk0p3", BootUtilitiesSetActivePart:"", BootUtilitiesGetNextActivePart:"" , DeviceTypeFile:"", DBus:conf.DBusConfig{Enabled:true}, UpdateControlMapExpirationTimeSeconds:0, UpdateControlMapBootExpirationTimeSeconds:0, UpdatePollIntervalSeconds:1800, InventoryPollIntervalSeconds:28800, SkipVerify:false, RetryPollIntervalSeconds: 300, RetryPollCount:0, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ModuleTimeoutSeconds:0, ServerCertificate:"", ServerURL:"https://mender.company-name.ht", UpdateLogPath:"", TenantToken:"dummy", Servers:[] client.MenderServer(nil), DaemonLogLevel:""}, ModulesPath:"/usr/share/mender/modules/v3", ModulesWorkPath:"/var/lib/mender/modules/v3", ArtifactScriptsPath:"/var/lib/mender/scripts", RootfsScriptsPath:"/etc/mender/scripts", BootstrapArtifactFile:"/var/li b/mender/bootstrap.mender"} [2023-07-12 13:45:38] DEBU[0000]/conf/config.go:215 conf.(*MenderConfig).Validate() Verified configuration = &conf.MenderConfig{MenderConfigFromFile:conf.MenderConfigFromFile{ArtifactVerifyKey:"", ArtifactVerifyKeys:[]string{"/etc/mender/artifact-verify-key.pem"}, HttpsClient:client.HttpsClient{Certificate:"", Key:"", SSLEngine:"" }, Security:client.Security{AuthPrivateKey:"", SSLEngine:""}, Connectivity:client.Connectivity{DisableKeepAlive:false, IdleConnTimeoutSeconds:0}, RootfsPartA:"/dev/mmcblk0p2", RootfsPartB:"/dev/mmcblk0p3", BootUtilitiesSetActivePart:"", BootUtilitiesGetN extActivePart:"", DeviceTypeFile:"/var/lib/mender/device_type", DBus:conf.DBusConfig{Enabled:true}, UpdateControlMapExpirationTimeSeconds:0, UpdateControlMapBootExpirationTimeSeconds:0, UpdatePollIntervalSeconds:1800, InventoryPollIntervalSeconds:28800, SkipVerify:false, RetryPollIntervalSeconds:300, RetryPollCount:0, StateScriptTimeoutSeconds:0, StateScriptRetryTimeoutSeconds:0, StateScriptRetryIntervalSeconds:0, ModuleTimeoutSeconds:0, ServerCertificate:"", ServerURL:"https://mender.company-name.ht", Update LogPath:"", TenantToken:"dummy", Servers:[]client.MenderServer{client.MenderServer{ServerURL:"https://mender.company-name.ht"}}, DaemonLogLevel:""}, ModulesPath:"/usr/share/mender/modules/v3", ModulesWorkPath:"/var/lib/mender/modules/v3", ArtifactScriptsPath:" /var/lib/mender/scripts", RootfsScriptsPath:"/etc/mender/scripts", BootstrapArtifactFile:"/var/lib/mender/bootstrap.mender"} [2023-07-12 13:45:38] DEBU[0000]/cli/cli.go:513 cli.(*runOptionsType).handleCLIOptions() calling doHandleBootstrapArtifact [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "grub-mender-grubenv-print", but it was not found [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "systemd-boot-printenv", but it was not found [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:274 installer.(*UBootEnv).getEnvironmentVariable() Have bootloader variable: mender_check_saveenv_canary=1 [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:307 installer.(*UBootEnv).getEnvironmentVariable() List of bootloader variables:map[mender_check_saveenv_canary:1] [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "grub-mender-grubenv-print", but it was not found [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "systemd-boot-printenv", but it was not found [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:274 installer.(*UBootEnv).getEnvironmentVariable() Have bootloader variable: mender_saveenv_canary=1 [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:307 installer.(*UBootEnv).getEnvironmentVariable() List of bootloader variables:map[mender_saveenv_canary:1] [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "grub-mender-grubenv-print", but it was not found [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "systemd-boot-printenv", but it was not found [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:274 installer.(*UBootEnv).getEnvironmentVariable() Have bootloader variable: mender_boot_part=2 [2023-07-12 13:45:40] DEBU[0002]/installer/bootenv.go:307 installer.(*UBootEnv).getEnvironmentVariable() List of bootloader variables:map[mender_boot_part:2] [2023-07-12 13:45:40] DEBU[0002]/installer/partitions.go:194 installer.(*partitions).getAndCacheActivePartition() Setting active partition from mount candidate: /dev/mmcblk0p2 [2023-07-12 13:45:40] INFO[0002]/cli/commands.go:83 cli.initDualRootfsDevice() Mender running on partition: /dev/mmcblk0p2 [2023-07-12 13:45:40] DEBU[0002]/app/updatemanager.go:369 app.(*ControlMapPool).loadFromStore() Loading update control maps from the store [2023-07-12 13:45:40] DEBU[0002]/app/updatemanager.go:373 app.(*ControlMapPool).loadFromStore() No Update Control Maps found in database. [2023-07-12 13:45:40] DEBU[0002]/installer/modules.go:859 installer.NewModuleInstallerFactory() ModuleTimeoutSeconds not set. Defaulting to 14400 seconds [2023-07-12 13:45:42] DEBU[0004]/app/mender.go:723 app.(*Mender).HandleBootstrapArtifact() No state data stored [2023-07-12 13:45:42] DEBU[0004]/app/mender.go:738 app.(*Mender).HandleBootstrapArtifact() Bootstrap Artifact /var/lib/mender/bootstrap.mender not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "grub-mender-grubenv-print", but it was not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "systemd-boot-printenv", but it was not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:274 installer.(*UBootEnv).getEnvironmentVariable() Have bootloader variable: mender_check_saveenv_canary=1 [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:307 installer.(*UBootEnv).getEnvironmentVariable() List of bootloader variables:map[mender_check_saveenv_canary:1] [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "grub-mender-grubenv-print", but it was not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "systemd-boot-printenv", but it was not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:274 installer.(*UBootEnv).getEnvironmentVariable() Have bootloader variable: mender_saveenv_canary=1 [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:307 installer.(*UBootEnv).getEnvironmentVariable() List of bootloader variables:map[mender_saveenv_canary:1] [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "grub-mender-grubenv-print", but it was not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:253 installer.(*UBootEnv).getEnvironmentVariable() Tried command "systemd-boot-printenv", but it was not found [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:274 installer.(*UBootEnv).getEnvironmentVariable() Have bootloader variable: mender_boot_part=2 [2023-07-12 13:45:42] DEBU[0004]/installer/bootenv.go:307 installer.(*UBootEnv).getEnvironmentVariable() List of bootloader variables:map[mender_boot_part:2] [2023-07-12 13:45:42] DEBU[0004]/installer/partitions.go:194 installer.(*partitions).getAndCacheActivePartition() Setting active partition from mount candidate: /dev/mmcblk0p2 [2023-07-12 13:45:42] INFO[0004]/cli/commands.go:83 cli.initDualRootfsDevice() Mender running on partition: /dev/mmcblk0p2 [2023-07-12 13:45:42] DEBU[0004]/installer/modules.go:859 installer.NewModuleInstallerFactory() ModuleTimeoutSeconds not set. Defaulting to 14400 seconds [2023-07-12 13:45:42] DEBU[0004]/device/device.go:141 device.(*DeviceManager).getValueFromDatabaseKey() Returning artifact-name value augmented-lidar-os_DEVONLY_5.12.0-alpha1-3-g7d53a27_fix_random_build_issue from database. ``` ---
**Author:** ![clementp](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/clementp/32/1392_2.png) [@clementp](https://hub.mender.io/u/clementp)\ **Post date:** [July 13, 2023, 1:59pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/4 "2023-07-13T13:59:48Z")
@TheYoctoJester @lluiscampos I can have a look but i’m not sure where to start. It seems that the database should have been created no ? ---
**Author:** ![TheYoctoJester](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/theyoctojester/32/1444_2.png) [@TheYoctoJester](https://hub.mender.io/u/TheYoctoJester)\ **Post date:** [July 14, 2023, 11:30am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/5 "2023-07-14T11:30:12Z")
@clementp @antony @Akshay as this seems to all be correlated - is the delay/resource consumption only happening once? Or on every invocation? Greetz, Josef ---
**Author:** ![Akshay](https://avatars.discourse-cdn.com/v4/letter/a/3ab097/32.png) [@Akshay](https://hub.mender.io/u/Akshay)\ **Post date:** [July 14, 2023, 11:34am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/6 "2023-07-14T11:34:33Z")
Hi Josef, The resource consumption occurs on every invocation because of which CPU utilization is increasing very frequently. Regards, Akshay Naik ---
**Author:** ![antony](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/antony/32/1422_2.png) [@antony](https://hub.mender.io/u/antony)\ **Post date:** [July 14, 2023, 11:57am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/7 "2023-07-14T11:57:22Z")
Hi Josef, The delay is every invocation (and unsurprisingly also impacts `show-provides` as well). Kind regards, Antony. ---
**Author:** ![Akshay](https://avatars.discourse-cdn.com/v4/letter/a/3ab097/32.png) [@Akshay](https://hub.mender.io/u/Akshay)\ **Post date:** [July 17, 2023, 6:42am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/8 "2023-07-17T06:42:12Z")
Hi Josef, Hope everything is good. Please let us know if there is any update on CPU utilization issue. Regards, Akshay Naik ---
**Author:** ![TheYoctoJester](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/theyoctojester/32/1444_2.png) [@TheYoctoJester](https://hub.mender.io/u/TheYoctoJester)\ **Post date:** [July 18, 2023, 9:48am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/9 "2023-07-18T09:48:08Z")
Hi @Akshay, The issue is being tracked at [[MEN-6618] - Mender and CFEngine (by Northern.tech) Jira](https://northerntech.atlassian.net/browse/MEN-6618) now. Greetz, Josef ---
**Author:** ![TheYoctoJester](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/theyoctojester/32/1444_2.png) [@TheYoctoJester](https://hub.mender.io/u/TheYoctoJester)\ **Post date:** [July 19, 2023, 2:10pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/10 "2023-07-19T14:10:29Z")
Update @Akshay @antony @clementp: We have identified this is a high priority item and will address it immediately as we take regressions very seriously. I will keep you updated on the topic. Thank you all for reporting, helping us fixing things and getting better! Greetz, Josef ---
**Author:** ![clementp](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/clementp/32/1392_2.png) [@clementp](https://hub.mender.io/u/clementp)\ **Post date:** [July 26, 2023, 5:01pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/11 "2023-07-26T17:01:28Z")
Fix has been merged in 3.5.x, now we just need to wait for a 3.5.1 release 😃 ---
**Author:** ![clementp](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/clementp/32/1392_2.png) [@clementp](https://hub.mender.io/u/clementp)\ **Post date:** [July 31, 2023, 8:13pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/12 "2023-07-31T20:13:14Z")
@Akshay @antony it’s now available on meta-mender FYI. > **[Commits · mendersoftware/meta-mender](https://github.com/mendersoftware/meta-mender/commits/kirkstone)** > > Yocto Project meta layer for the Mender client. Contribute to mendersoftware/meta-mender development by creating an account on GitHub. ---
**Author:** ![Akshay](https://avatars.discourse-cdn.com/v4/letter/a/3ab097/32.png) [@Akshay](https://hub.mender.io/u/Akshay)\ **Post date:** [August 1, 2023, 4:08am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/13 "2023-08-01T04:08:05Z")
Hi Clement, Thanks for the update. We will try downloading and testing it. Will let you know if there are any concerns. Regards, Akshay Naik ---
**Author:** ![clementp](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/clementp/32/1392_2.png) [@clementp](https://hub.mender.io/u/clementp)\ **Post date:** [August 3, 2023, 3:31pm UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/14 "2023-08-03T15:31:59Z")
It’s a bit better but not as fast as before no? ---
**Author:** ![Akshay](https://avatars.discourse-cdn.com/v4/letter/a/3ab097/32.png) [@Akshay](https://hub.mender.io/u/Akshay)\ **Post date:** [August 7, 2023, 7:37am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/15 "2023-08-07T07:37:52Z")
Hi Clement, We tested the latest mender and as you mentioned its slower and also we observed that the CPU utilization has reduced a bit. The CPU utilization is around 60% to 83% and sometimes it moves up to 90%. Did you observe the same behaviour ? Is there any impact for the other process due to this? Will there be any further updates which might reduce the CPU utilization? Regards, Akshay Naik ---
**Author:** ![antony](https://yyz2.discourse-cdn.com/flex036/user_avatar/hub.mender.io/antony/32/1422_2.png) [@antony](https://hub.mender.io/u/antony)\ **Post date:** [August 7, 2023, 8:23am UTC](https://hub.mender.io/t/delayed-output-from-mender-show-artifact/5856/16 "2023-08-07T08:23:18Z")
Hi, These are the timings I now see after building the HEAD of master of the mender client (SHA bbe854ce): ```auto # mender -l info show-artifact |& cat - time="2023-08-07T08:17:35Z" level=info msg="Loaded configuration file: /etc/mender/mender.conf" time="2023-08-07T08:17:35Z" level=info msg="'UpdateControlMapExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 2*UpdatePollIntervalSeconds" time="2023-08-07T08:17:35Z" level=info msg="'UpdateControlMapBootExpirationTimeSeconds' is not set in the Mender configuration file. Falling back to the default of 600 seconds" time="2023-08-07T08:17:35Z" level=info msg="Mender running on partition: /dev/mmcblk0p2" time="2023-08-07T08:17:38Z" level=info msg="Mender running on partition: /dev/mmcblk0p2" build_20230730_554 ``` A delay is still present, but now only one (not two as before). Note that on our system we do not see any significant CPU load from the client (but we are running the self-hosted community edition of mender server). Kind regards, Antony.