2

This morning we saw a step increase in CPU utilization and load on our web server, call it host1. Overall CPU usage went from approximately 100% to 500% (on 16 cores, 32 hyperthreads), and load from < 1 to ~6 average. It then remained at that increased level. Using top, it's clear that the added CPU usage is all by Apache (httpd processes). (We're on Apache 2.4.39, on CentOS 7.6.)

PHP processes and mariadb connections are both unchanged from their baseline levels. Data transferred over the server's network connection is unchanged. Requests served per minute, based on line counts of the server's domlogs are unchanged. There has been no increase in disk utilization, wait time, or service time. Memory usage is also flat.

I checked the Apache error log for the time when the load jumped up, and didn't see anything new, nor did Apache restart at that time.

As a test, I moved all our web traffic from host1 to an effectively identical backup server, host2. Once the traffic was migrated, host1 cpu usage dropped to near zero (a drop of ~400% at that point), while the usage on host2 increased to only ~80%, about the level host1 was running at before the sudden increase. So, whatever changed, it's something to do with that specific server, not with the nature of our web traffic.

I checked the apache configurations on both servers, and as expected, they are identical. Looking at apache status, # of simultaneous connections appears to be roughly double on host1 compared to host2. This is as you would expect given higher load/cpu usage. It's taking longer to serve requests, so we have more simultaneous connections sticking around for the same throughput. Subjectively, it seems like some requests are returning in a normal amount of time on host1, while others are taking significantly longer than usual (seconds rather than the expected milliseconds). That could be a cause or a consequence of the higher load though.

I tried disabling mod_security on host1, and ruled that out as the cause. Next I tried rebooting host1 completely, but after transferring traffic back, the high load persisted. Any idea what else might cause apache on a particular server to suddenly and persistently start using more cpu and taking longer to serve the same volume of requests?

Edit: for what it's worth, both system and user cpu use stepped up proportionally.

Edit 2: Results of perf top:

Samples: 905K of event 'cycles:ppp', Event count (approx.): 111054988919
Overhead  Shared Object             Symbol
  16.69%  [kernel]                  [k] system_call_after_swapgs
  11.02%  [kernel]                  [k] sysret_check
   5.64%  [kernel]                  [k] copy_user_enhanced_fast_string
   3.79%  [kernel]                  [k] fget_light
   3.04%  [kernel]                  [k] __audit_syscall_exit
   3.01%  [kernel]                  [k] generic_file_aio_read
   2.51%  [kernel]                  [k] __audit_syscall_entry
   1.78%  [kernel]                  [k] sys_lseek
   1.63%  [kernel]                  [k] __radix_tree_lookup
   1.45%  [kernel]                  [k] sys_read
   1.43%  libpthread-2.17.so        [.] __pthread_disable_asynccancel
   1.32%  [kernel]                  [k] touch_atime
   1.28%  [kernel]                  [k] ext4_file_read
   1.23%  [kernel]                  [k] radix_tree_descend
   1.11%  [kernel]                  [k] mutex_lock
   1.08%  [kernel]                  [k] vfs_read
   1.04%  [kernel]                  [k] file_read_actor
   0.95%  libapr-1.so.0.6.5         [.] apr_file_read
   0.85%  [kernel]                  [k] do_sync_read
   0.84%  [kernel]                  [k] __d_lookup_rcu
   0.81%  [kernel]                  [k] __x86_indirect_thunk_rax
   0.79%  [kernel]                  [k] fsnotify
   0.78%  [kernel]                  [k] generic_segment_checks
   0.77%  [kernel]                  [k] __check_object_size
   0.74%  [kernel]                  [k] current_kernel_time
   0.73%  libapr-1.so.0.6.5         [.] apr_file_read_full
   0.71%  [kernel]                  [k] put_page
   0.70%  [kernel]                  [k] ext4_llseek
   0.70%  php-fpm                   [.] execute_ex
   0.69%  libaprutil-1.so.0.6.1     [.] getpage
   0.65%  [kernel]                  [k] _cond_resched
   0.64%  libaprutil-1.so.0.6.1     [.] read_from
   0.59%  [kernel]                  [k] strncpy_from_user
   0.59%  libpthread-2.17.so        [.] llseek
   0.57%  [kernel]                  [k] __fsnotify_parent
   0.57%  [kernel]                  [k] cleanup_module
   0.55%  [kernel]                  [k] rw_verify_area
   0.55%  [kernel]                  [k] __find_get_page
   0.51%  [kernel]                  [k] auditsys
   0.51%  [kernel]                  [k] security_file_permission
   0.48%  php-fpm                   [.] _is_numeric_string_ex
   0.47%  [kernel]                  [k] unroll_tree_refs
   0.47%  libapr-1.so.0.6.5         [.] apr_file_seek
   0.42%  [kernel]                  [k] generic_file_llseek_size
   0.41%  [kernel]                  [k] fput
   0.40%  php-fpm                   [.] zend_hash_find
   0.35%  [kernel]                  [k] __virt_addr_valid
   0.30%  [kernel]                  [k] path_put
   0.27%  libaprutil-1.so.0.6.1     [.] getnext
   0.27%  libz.so.1.2.7             [.] 0x0000000000002d11
   0.27%  [kernel]                  [k] tracesys
   0.27%  [unknown]                 [k] 0x00002af9a2716d7b
   0.27%  [kernel]                  [k] lookup_fast
   0.25%  [kernel]                  [k] mutex_unlock
   0.25%  [kernel]                  [k] kfree
   0.24%  [kernel]                  [k] current_fs_time

For comparison, here are the results from our other server, host2, which is handling a comparable amount of web traffic, plus all our databases currently, and isn't experiencing this high load issue:

Samples: 1M of event 'cycles:ppp', Event count (approx.): 104427407206424
Overhead  Shared Object                  Symbol
  27.34%  [kernel]                       [k] retint_userspace_restore_args
  13.57%  php-fpm                        [.] zend_do_inheritance
   7.56%  [kernel]                       [k] handle_mm_fault
   7.56%  httpd                          [.] 0x000000000004470e
   6.87%  libpthread-2.17.so             [.] pthread_cond_broadcast@@GLIBC_2.3.2
   4.43%  [kernel]                       [k] cpuidle_enter_state
   3.31%  libc-2.17.so                   [.] __memmove_ssse3_back
   3.31%  [unknown]                      [.] 0x00002b8a4d236777
   2.68%  [kernel]                       [k] cap_inode_permission
   2.09%  libperl.so                     [.] S_refto
   2.09%  [unknown]                      [k] 0x00007f4479518900
   1.37%  [kernel]                       [k] free_pages_prepare
   1.20%  [kernel]                       [k] hrtimer_interrupt
   0.90%  [kernel]                       [k] irq_return
   0.89%  [kernel]                       [k] change_pte_range
   0.76%  httpd                          [.] ap_find_command
   0.69%  [unknown]                      [k] 0x00007fe15a923be8
   0.68%  [kernel]                       [k] lookup_fast
   0.60%  libperl.so                     [.] Perl_runops_standard
   0.60%  libperl.so                     [.] Perl_pp_multideref
   0.60%  [unknown]                      [.] 0x00007f227838a777
   0.55%  [kernel]                       [k] system_call_after_swapgs
   0.46%  [unknown]                      [.] 0x00007f18e7736015
   0.45%  libc-2.17.so                   [.] __memcpy_ssse3_back
   0.40%  mysqld                         [.] 0x0000000000b643c4
   0.40%  ld-2.17.so                     [.] _dl_map_object_deps
   0.39%  [unknown]                      [.] 0x00007f81151f761c
   0.35%  [kernel]                       [k] kmem_cache_alloc
   0.35%  [kernel]                       [k] vma_interval_tree_insert
   0.30%  [kernel]                       [k] _raw_spin_lock_irqsave
   0.30%  libc-2.17.so                   [.] __readdir_r
   0.30%  [kernel]                       [k] tick_do_update_jiffies64
   0.30%  libpng15.so.15.13.0            [.] 0x000000000001ff7f
   0.30%  [unknown]                      [.] 0x00007f2a3ffee13c
   0.30%  libpthread-2.17.so             [.] __ctype_init@plt
   0.26%  libc-2.17.so                   [.] _int_malloc
   0.26%  libc-2.17.so                   [.] malloc
   0.26%  libc-2.17.so                   [.] malloc_consolidate
   0.26%  [kernel]                       [k] mem_cgroup_charge_common
   0.26%  libperl.so                     [.] Perl_hv_common
   0.26%  [kernel]                       [k] pid_revalidate
   0.26%  libperl.so                     [.] Perl_sv_eq_flags
   0.26%  libcairo.so.2.11512.0          [.] 0x000000000004bf43
   0.26%  libperl.so                     [.] S_dopoptosub_at
   0.26%  libcairo.so.2.11512.0          [.] 0x00000000000d059a

host2 is much more variable in terms of the top functions though; this is just one example. host1 (the one with the problem) has a very stable top few entries in the list.

Edit 3: Having tracked the issue down to mod security, I've specifically found it appears to be related to the IP address database, /tmp/ip.pag, growing indefinitely, despite the pruning timeouts we have in place. Clearing this file resolves the high CPU usage without disabling mod security entirely. However it will presumably grow again if we continue using IP based rules, so we're looking into modifying our rules, or may just set up a daily cron to clear out any old IPs in the file.

  • 1
    Install debug symbols: yum --enablerepo=base-debuginfo install kernel-debuginfo-$(uname -r) httpd-debuginfo then run perf top. What are the top functions? – John Mahowald Apr 14 at 12:22
  • @JohnMahowald got repository not found for base-debuginfo. I was able to yum install perf and get a perf top output, but it doesn't appear to include httpd stuff. Any idea how to get httpd-debuginfo installed? I'll also look into it. – Nathan Stretch Apr 14 at 19:07
  • Just looking at the info perf top is currently giving me, the top two are system_call_after_swapgs, and sysret_check. Doing a bit of googling, it sounds like an increase in these could be related to Spectre mitigation? Not sure why that would have suddenly changed though, without a kernel update. Probably need that httpd perf info. – Nathan Stretch Apr 14 at 19:12
  • 1
    Edit your question to add a screen of perf top. Top tasks will appear even without debug symbols, just without human readable function names. – John Mahowald Apr 14 at 20:03
  • Done @JohnMahowald – Nathan Stretch Apr 15 at 3:59
3

First sanity check if the kernel is trying to tell you something. Maybe about the storage system because of the storage stack appearing the samples. Review the output of dmesg and syslog log files.


Your problem host is spending more time in the kernel. Contrast that to the other host where php-fpm and httpd are in the top 5. Most workloads do useful services in user space, so low kernel overhead is good.

Note the time spent in the audit interfaces. And I think fsnotify is used by the audit system as well. Review any audit rules, including file system and system calls. Auditing anything like all reads is very expensive. See the documentation of the auditd package for examples of targeted auditing in a few scenarios.

Lots of detail about what Linux is up to is possible if you profile further. Use perf to count syscalls. Also possible is getting the entire call graph in a flame graph visualization.

Edit: those flame graphs are particularly useful in a high CPU utilization scenario if you have symbols. You can compare to problem stacks in issue reports, and dig further into the specific function that was taking a long time.

Install yum-utils and use this to install symbols: debuginfo-install --enablerepo=base-debuginfo httpd (It is a convenience script so you don't have to know the -debuginfo postfix convention.)

You found ModSecurity issue Spontaneously high CPU usage #890. I don't actually see stack like that yet on your flame graphs. But if you install debug symbols you can see things that are interactions between APR, the module code, and the OS kernel, beyond just one of those.

  • Nothing unusual in dmesg or syslog—both are comparable to other server. Audit system is enabled, but no rules are defined (on both servers). Out of my depth on the perf stats stuff, but will look into it. – Nathan Stretch Apr 16 at 0:25
  • Running perf-stat for 5 seconds a few times, the most obvious difference between the two servers is that page-faults is roughly double on host1. Instructions, branches, and branch-misses are all much more consistent on host2 and jump around more on host1 (lower and higher than the host2 level). (Although this consistency could be because most of the load on host2 is database stuff, whereas host1 is only handling some web server requests, and whatever is causing this issue.) – Nathan Stretch Apr 16 at 0:29
  • 1
    Take a step back and evaluate whether you have an actual end user response time problem. If you do want to continue to spend the effort, keep looking. In particular, use perf record to generate a flame graph and add it to your question: brendangregg.com/FlameGraphs/cpuflamegraphs.html#Instructions – John Mahowald Apr 16 at 12:45
  • 1
    Edited in more detail about flame graphs and debug symbols. As of now, your graph is missing httpd symbols as it has a big chunk of [unknown]. So that find is due to searching issues list of software, always a good idea as well. – John Mahowald Apr 17 at 13:00
  • 1
    Your yum repos do not match what I expect from CentOS 7. Dig around in the mirror at debuginfo.centos.org/7/x86_64 and use yum install on the httpd-debuginfo of the same version that you have installed. – John Mahowald Apr 18 at 15:54

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.