Re: 100% CPU utilization by mod_authz_svn

Den fre 22 dec. 2023 kl 12:22 skrev radek.krotil.siemens.com via users <
[email protected]>:

> Hi SVN Community.
>
>
>
> I’d like to consult a problem with occasional high CPU utilization by
> mod_authz_svn. Please, do CC me and my colleague in the response, because
> we are subscribed to the list.
>
>
>
> Our Java application uses Subversion as a primary data storage and the SVN
> data are being accessed via Apache HTTPD mod_dav_svn and also by svnserve
> server on top of the same repository.
>
>
>
> We are facing a problem in one of our productive environments hosted in
> AWS. The server is running RHEL 8.8, Apache 2.4.37 with SVN 1.14.1
> binaries. Occasionally, the Apache HTTPD is acting strange, utilizing 100%
> CPU for periods of minutes to tens of minutes. This situation happens
> several times a week and causes delayed responses from the SVN server up to
> several minutes. Similar behavior is visible on several httpd server
> processes (mpm_event module is used), where each of them has tens of active
> requests being processed. When this CPU spike occurs, there several Apache
> HTTPD server processes with tens of threads busy in the following code
> related to the Subversion ACL.
>
>
>
> The access file is quite big. It contains about 20000 group definitions
> with roughly 10000 users assigned to them and about 35000 authorization
> rules for 15000 paths, and it’s size is over 5 MB. The access file is
> getting changed 100 times a day, but the CPU spikes do not correlate with
> the CPU spikes.
>
>
>
> Initially we suspected filesystem issues, but we were not able to confirm
> them. When the spike occurs, CPU I/O wait goes to zero and all the CPU is
> consumed in user space.
>
>
>
> We are looking for suggestions how to further troubleshoot the problem, or
> possible confirmation that this is a Subversion bug or inefficiency.
>
>
>
> Thank you,
>
> Radek Krotil
>
> Siemens Digital Industries Software
>
>
>
>
>
> *Pstack output example*
>
> Thread 127 (Thread 0x7f0003fcf700 (LWP 2934729)):
>
>
>
> #0  0x00007f0049b79b60 in svn_authz.get_acl_access () from
> target:/lib64/libsvn_repos-1.so.0
>
> #1  0x00007f0049b7a864 in update_user_rights () from
> target:/lib64/libsvn_repos-1.so.0
>
> #2  0x00007f0048e35d06 in hash_do_callback () from
> target:/lib64/libsvn_subr-1.so.0
>
> #3  0x00007f0058bc8ebe in apr_hash_do () from target:/lib64/libapr-1.so.0
>
> #4  0x00007f0048e35d6a in svn_iter_apr_hash () from
> target:/lib64/libsvn_subr-1.so.0
>
> #5  0x00007f0049b7a7b4 in expand_acl_callback () from
> target:/lib64/libsvn_repos-1.so.0
>
> #6  0x00007f0048e35e41 in svn_iter_apr_array () from
> target:/lib64/libsvn_subr-1.so.0
>
> #7  0x00007f0049b7c109 in svn_authz.parse () from
> target:/lib64/libsvn_repos-1.so.0
>
> #8  0x00007f0049b78f74 in svn_repos_authz_read4 () from
> target:/lib64/libsvn_repos-1.so.0
>
> #9  0x00007f004845e4a3 in get_access_conf () from
> target:/etc/httpd/modules/mod_authz_svn.so
>
> #10 0x00007f004845e705 in req_check_access () from
> target:/etc/httpd/modules/mod_authz_svn.so
>
> #11 0x00007f004845efd6 in auth_checker () from
> target:/etc/httpd/modules/mod_authz_svn.so
>
> #12 0x0000561c8b0724c8 in ap_run_auth_checker ()
>
> #13 0x0000561c8b074a9c in ap_process_request_internal ()
>
> #14 0x0000561c8b093a70 in ap_process_async_request ()
>
> #15 0x0000561c8b08fed0 in ap_process_http_connection ()
>
> #16 0x0000561c8b0862b8 in ap_run_process_connection ()
>
> #17 0x00007f004d6b9a47 in process_socket () from
> target:/etc/httpd/modules/mod_mpm_event.so
>
> #18 0x00007f004d6ba3ea in worker_thread () from
> target:/etc/httpd/modules/mod_mpm_event.so
>
> #19 0x00007f005899a1ca in start_thread () from
> target:/lib64/libpthread.so.0
>
> #20 0x00007f0058402e73 in clone () from target:/lib64/libc.so.6
>
>
>
>
>
> *TOP output looks as follows*
>
> top - 13:00:01 up 15 days,  7:09,  0 users,  load average: 129.31, 100.24,
> 53.38
>
> Tasks: 241 total,   7 running, 233 sleeping,   0 stopped,   1 zombie
>
> %Cpu(s): 95.6 us,  3.7 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.7 hi,  0.0
> si,  0.0 st
>
> MiB Mem : 126914.0 total,  55179.2 free,  20765.8 used,  50969.0 buff/cache
>
> MiB Swap:      0.0 total,      0.0 free,      0.0 used. 104540.6 avail Mem
>
>
>
>     PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+
> COMMAND
>
>  233319 apache    20   0 5818164   2.9g  13844 S 456.2   2.3 183:35.14
> httpd
>
>  233318 apache    20   0 5751168   2.7g  13844 S 443.8   2.2 127:53.12
> httpd
>
>  232848 apache    20   0 5226028   2.0g  13844 S 218.8   1.6  46:08.83
> httpd
>
>  232849 apache    20   0 5291384   2.1g  13804 S 168.8   1.7  68:34.92
> httpd
>
>  232847 apache    20   0 5291628   1.7g  13908 S 137.5   1.4  39:14.61
> httpd
>
>
>
> *And Apache server status clearly shows the number of “stuck” requests*
>
> Apache Server Status for localhost (via ::1)
>
> Server Version: Apache/2.4.37 (Red Hat Enterprise Linux) OpenSSL/1.1.1k
> SVN/1.14.1
>
> Server MPM: event
>
> Server Built: Aug 17 2023 10:52:25
> ------------------------------
>
> Current Time: Monday, 18-Dec-2023 13:00:01 UTC
>
> Restart Time: Saturday, 16-Dec-2023 05:23:02 UTC
>
> Parent Server Config. Generation: 2
>
> Parent Server MPM Generation: 1
>
> Server uptime: 2 days 7 hours 36 minutes 58 seconds
>
> Server load: 129.31 100.24 53.38
>
> Total accesses: 212201 - Total Traffic: 1.9 GB - Total Duration: 67348142
>
> CPU Usage: u27647.8 s220.14 cu338.36 cs31.99 - 14.1% CPU load
>
> 1.06 requests/sec - 10.0 kB/second - 9.4 kB/request - 317.379 ms/request
>
> 112 requests currently being processed, 0 workers gracefully restarting,
> 138 idle workers
>
> *Slot*
>
> *PID*
>
> *Stopping*
>
> *Connections*
>
> *Threads*
>
> *Async connections*
>
> *total*
>
> *accepting*
>
> *busy*
>
> *graceful*
>
> *idle*
>
> *writing*
>
> *keep-alive*
>
> *closing*
>
> 0
>
> 232847
>
> no
>
> 12
>
> yes
>
> 11
>
> 0
>
> 39
>
> 0
>
> 0
>
> 1
>
> 1
>
> 232848
>
> no
>
> 11
>
> yes
>
> 11
>
> 0
>
> 39
>
> 0
>
> 0
>
> 0
>
> 3
>
> 232849
>
> no
>
> 15
>
> yes
>
> 15
>
> 0
>
> 35
>
> 0
>
> 0
>
> 0
>
> 5
>
> 233318
>
> no
>
> 40
>
> yes
>
> 37
>
> 0
>
> 13
>
> 0
>
> 0
>
> 2
>
> 6
>
> 233319
>
> no
>
> 37
>
> yes
>
> 38
>
> 0
>
> 12
>
> 0
>
> 0
>
> 0
>
> Sum
>
> 5
>
> 0
>
> 115
>
>
>
> 112
>
> 0
>
> 138
>
> 0
>
> 0
>
> 3
>
> W___W____W_____________WWW__W_______W__W__W_W_____W_W_____WW_W__
>
> W__W____W____________W______WW______............................
>
> ......................_W__W____W_W____WWW__WW_W____W___W_____WW_
>
> _W______..................................................WWWW__
>
> WWWWW_WWWW_WWW_WWWWWW_W_WWW__W_W_WWW__WWWWWWWWWWW__WWWW_WW_W_W_W
>
> WW__WW_WW_W_WWWWW_WWWWWWWWWWWW..................................
>
> ................................................................
>
> ................................................................
>
> ................................................................
>
> ................................................................
>
> ................................................................
>
> ................................................................
>
> ................................
>
> Scoreboard Key:
> "*_*" Waiting for Connection, "*S*" Starting up, "*R*" Reading Request,
> "*W*" Sending Reply, "*K*" Keepalive (read), "*D*" DNS Lookup,
> "*C*" Closing connection, "*L*" Logging, "*G*" Gracefully finishing,
> "*I*" Idle cleanup of worker, "*.*" Open slot with no current process
>
> *Srv*
>
> *PID*
>
> *Acc*
>
> *M*
>
> *CPU*
>
> *SS*
>
> *Req*
>
> *Dur*
>
> *Conn*
>
> *Child*
>
> *Slot*
>
> *Client*
>
> *Protocol*
>
> *VHost*
>
> *Request*
>
> *0-1*
>
> 232847
>
> 0/20/27
>
> *W*
>
> 1796.47
>
> 183
>
> 0
>
> 77128
>
> 0.0
>
> 0.25
>
> 0.28
>
> 10.X.X.239
>
> http/1.1
>
> xyz:443
>
> PROPFIND /repo/.polarion/user-management/users/…
>
> *0-1*
>
> 232847
>
> 0/23/32
>
> *W*
>
> 1761.15
>
> 201
>
> 0
>
> 190003
>
> 0.0
>
> 0.18
>
> 0.23
>
> 10.X.X.239
>
> http/1.1
>
> xyz:443
>
> GET /repo/!svn/bc/1731720/External/…
>
> *0-1*
>
> 232847
>
> 0/24/35
>
> *W*
>
> 1752.23
>
> 182
>
> 0
>
> 81788
>
> 0.0
>
> 0.31
>
> 0.36
>
> 10.X.X.239
>
> http/1.1
>
> xyz:443
>
> GET /repo/!svn/bc/1743998/External/…
>
>
>
>
>

Hi,

There are other reports:

https://lists.apache.org/thread/4vzo7tddyv556vs372kxb4hz83lomcdr
https://lists.apache.org/thread/t9j8psdrkflfyb9rfb69dkq24lf26t84

Can you look at this to see if this is similar to your problem?

I don't know if anything was ever done to this, as far as I understand this
is caused by the parsing of the authorization file.

Kind regards,
Daniel