We were seeing some spike in CPU usage every 15 minutes on some new servers. As these systems were idle i.e. no workload apart from the operating system this makes an investigation slightly easier as we don’t have any application workloads to add to the mix.

Below we can see an example of the spikes in CPU, the systems here have 48 cores and 96 hyper threads so we are hitting all hyper threads when this happens.

When we started to look at this we loads of errors in the messages file related to the udev daemon where these errors correlated to the CPU spikes.

Nov  1 11:02:59 xxxxxxx systemd-udevd: error opening ATTR{/sys/devices/pci0000:d7/0000:d7:00.0/0000:d8:00.0/host3/rport-3:0-2/target3:0:2/3:0:2:83/block/sdazy/sdazy3/queue/nr_requests} for writing: No such file or directory

Now this error was related to a typo in one of the udev rules which did not exclude partitions however when this was resolved the CPU spikes still occurred.

Investigation

We were not keen on disabling udev primarily as we have rules in place for when we add new disks to a server we apply appropriate settings under /sys/block/dev/queue/scheduler|nr_requests|add_random|rotational|rq_affinty.

But what was triggering udev to fire? My first thought was let’s get a list of all processes running on the system every second prior to this starting since we know it’s going to kick in on a 15 minute interval, once we have that we can do a quick eyeball and see if anything stands out.
So a script was setup to run a ps –eLf >> log ; sleep 1 and we waited.

When the rules fired we could see these in the ps output and what we saw when the udev rules started was this.

root      5267     1  5267  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6023  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6825  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6826  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6843  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6844  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6846  0   23 Oct31 ?        00:00:01 storapid start -name storapid
root      5267     1  6847  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6859  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6860  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1  6862  0   23 Oct31 ?        00:00:09 storapid start -name storapid
root      5267     1 22214  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1 87368  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1 26523  0   23 Oct31 ?        00:00:00 storapid start -name storapid
root      5267     1 84334  0   23 14:28 ?        00:00:00 storapid start -name storapid
root      5267     1 95235  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95236  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95237  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95238  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95239  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95243  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95290  0   23 14:43 ?        00:00:00 storapid start -name storapid
root      5267     1 95291  0   23 14:43 ?        00:00:00 storapid start -name storapid

Followed by udev starting at the same time.

root     77973     1 77973  2    1 13:17 ?        00:02:31 /usr/lib/systemd/systemd-udevd
root     95326 77973 95326  6    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     95386 77973 95386  5    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     95501 77973 95501  6    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     95961 77973 95961  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     95973 77973 95973  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     95980 77973 95980  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     95988 77973 95988  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     96004 77973 96004  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     96040 77973 96040  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     96091 77973 96091  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     96160 77973 96160  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd
root     96181 77973 96181  0    1 14:43 ?        00:00:00 /usr/lib/systemd/systemd-udevd

We can see that the start times match for the storapid and the udev processes.
So what’s going on here? Well storapid is a Dell EMC product which is part of Solutions Enabler, this software is used to control EMC arrays. Looking at the storapid log we could see that the array was sending a scsi inquiry every 15 minutes which again correlated with the times of the spikes in CPU.

This was a good find and it explained why the udev was being triggered however why such high CPU usage?

udev and its children

So udev kicks in when we get the return from a scsi inquiry from the array, but why would this cause the large CPU spike?

Well udev has a setting which has a number of children this is set to 200 on this system which seems high. This is set to 8 + (num cpus) * 2. When the daemon kicks in it tries to run 200 threads concurrently to fulfil the udev requirements causing the CPU spikes.

We subsequently reduced the udev children to 8 which causes a 10% CPU spike upon a scsi inquiry (syminq) and around 4% on a discover (symcfg discover ). We then disabled the product from updating its memory cache via this inquiry data after checking with EMC that this was not used for anything which could impact failover. This ultimately stopped the scsi inquiry from being run, we do need to update the local symapi databases for some failover tasks however we know the impact of this moving forward.