Delayed output from mender show-artifact

General Discussions
1

Hi all,

We are using mender client version 3.5.0 (from 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:

# 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.

2

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.

3

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

~# 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.
4

@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 ?

5

@clementp @antony @Akshay as this seems to all be correlated - is the delay/resource consumption only happening once? Or on every invocation?

Greetz,
Josef

6

Hi Josef,

The resource consumption occurs on every invocation because of which CPU utilization is increasing very frequently.

Regards,
Akshay Naik

7

Hi Josef,
The delay is every invocation (and unsurprisingly also impacts show-provides as well).
Kind regards,
Antony.

8

Hi Josef,

Hope everything is good.
Please let us know if there is any update on CPU utilization issue.

Regards,
Akshay Naik

9

Hi @Akshay,

The issue is being tracked at [MEN-6618] - Mender and CFEngine (by Northern.tech) Jira now.

Greetz,
Josef

10

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

1 Like
11

Fix has been merged in 3.5.x, now we just need to wait for a 3.5.1 release :smiley:

1 Like
12

@Akshay @antony it’s now available on meta-mender FYI.

1 Like
13

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

14

It’s a bit better but not as fast as before no?

15

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

16

Hi,

These are the timings I now see after building the HEAD of master of the mender client (SHA bbe854ce):

# 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.