This discussion has been locked.

You can no longer post new replies to this discussion. If you have a question you can start a new discussion

Temporary 100% CPU Load - How to Identify Root Cause?

Hello Folks,

This is the situation:
From time to time (on a day/in a week) our Astaro ASG320 v.8.202 runs on 100% CPU. All inhouse Internet traffic is very slow then and users are complaining.

RAM is usually ~60% used, SWAP ~30% and Log and Data Disk have enough space.

Using the console and the "top" command it shows me among other information:


  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

19658 postgres  20   0 52616  35m  32m S 52.8  3.5   0:01.95 postgres

 4323 httpprox  20   0 1268m 288m 5048 S  38.6 28.7 432:21.06 httpproxy

These values differ. Sometimes the postgres and the httpproxy have a CPU load of 30-70% even. But everytime its these both services using most of the Astaro's device performance.

I GUESS someone causes some overload within the network.
I cannot figure out where from or who is doing so.
The users use the webfilter proxy to browse through the Internet.
Having the webfilter live log running there is nothing suspicious during those "slow" times.

We are using an Online Hard Disk service by Strato by the way. Users upload and download data mostly using a https (WebDAV) connection therefore.
The webfilter does NOT scan HTTPS traffic.

How can I identify and SOLVE the root cause of this 100% CPU load problem?

Thank you in advance!!
Regards,
Uwe

* * *

PS: Today this situation is happening very often! :-(

PPS: I cannot say that for sure but I think the following (and similar) webfilter live log lines occur when the CPU is on 100%:

2012:01:11-15:10:59 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_handle_cmd" file="scr_scanner.c" line="510" message="cffs11.astaro.com: write: Connection refused"



2012:01:11-15:15:03 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="confd_config_reload_func" file="confd-client.c" line="757" message="reloading config done, new version 25231"

2012:01:11-15:15:03 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="confd_config_reload_func" file="confd-client.c" line="722" message="reloading config"



2012:01:11-15:15:14 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="721" message="server 'cffs13.astaro.com' access time: 296ms"



012:01:11-15:45:55 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="721" message="server 'cffs10.astaro.com' access time: 706ms"

2012:01:11-15:45:55 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="721" message="server 'cffs12.astaro.com' access time: 99ms"

2012:01:11-15:45:55 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_handle_cmd" file="scr_scanner.c" line="510" message="cffs01.astaro.com: write: Connection refused"

2012:01:11-15:45:56 disgwac httpproxy[4323]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="sc_check_servers" file="scr_scanner.c" line="721" message="server 'cffs06.astaro.com' access time: 419ms"

This thread was automatically locked due to age.

Parents

0 UweT over 13 years ago

There is nothing unusual happening in the logs.

Currently we experiencing another 100% session again. It's one of a lot during a day.

Does that help?


USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND

(...)

root      4467  0.0  1.4  40500 14544 ?        Ss    2011 112:22 confd [master]

root      4468  0.0  0.0   1796   236 ?        S     2011   0:00  \_ logger -p daemon.debug -t confd[4467]

root      4907  0.0  0.6  39852  6492 ?        S     2011  13:49  \_ confd [listener]

root     19063  2.5  3.5  64584 36292 ?        S    13:10   0:38      \_ confd [worker[:P]rpc:webadmin]

root     21497  0.0  0.3   5820  3976 ?        Ss   13:32   0:00      |   \_ /usr/local/bin/traceable_system.plx /tmp/ts.19063.13263

root     21501  0.0  0.0   1832   492 ?        S    13:32   0:00      |   |   \_ /usr/bin/tail -n 10 -f /var/log/ips.log

root     21781  0.1  0.4   5952  4172 ?        Ss   13:34   0:00      |   \_ /usr/local/bin/traceable_system.plx /tmp/ts.19063.13263

root     21785  0.0  0.0   1832   500 ?        S    13:34   0:00      |   |   \_ /usr/bin/tail -n 10 -f /var/log/http.log

root     21904 33.3  0.0   2616   940 ?        R    13:35   0:00      |   \_ ps auxwf

root     20055  1.4  3.5  64388 36356 ?        S    13:22   0:12      \_ confd [worker[:P]rpc:webadmin]

root     21850  1.5  0.0      0     0 ?        Z    13:35   0:00      \_ [confd.plx] 

root     21851  1.4  0.0      0     0 ?        Z    13:35   0:00      \_ [confd.plx] 

root     21852  1.5  0.0      0     0 ?        Z    13:35   0:00      \_ [confd.plx] 

root      4533  0.0  0.2   7632  2588 ?        S     2011  30:45 /usr/local/bin/sysmond

root      4615  0.0  0.3  15424  3772 ?        S     2011   0:02 /var/aua/aua.bin

root     19064  0.0  0.0      0     0 ?        Z    13:10   0:00  \_ [aua.bin] 

root      4813  0.0  0.3  14056  3468 ?        S     2011   3:00 /usr/local/bin/notifier.plx -d

at        4821  0.0  0.0   2236    52 ?        Ss    2011   0:00 /usr/sbin/atd

postgres  4931  0.0  0.1  46772  1128 ?        S     2011   4:24 /usr/bin/postgres -D /var/storage/pgsql/data

postgres  4949  0.0  3.3  46860 34012 ?        Ss    2011  32:11  \_ postgres: writer process                    

postgres  4950  0.0  0.0  46772   352 ?        Ss    2011  33:31  \_ postgres: wal writer process                

postgres  4951  0.0  0.0  47044   784 ?        Ss    2011   7:43  \_ postgres: autovacuum launcher process       

postgres  4952  0.0  0.0   7356   700 ?        Ss    2011  17:39  \_ postgres: stats collector process           

postgres  5914  0.8  3.5  49648 36012 ?        Ss    2011 1038:45  \_ postgres: reporting reporting [local] idle  

postgres  6428  0.0  0.0  49184   868 ?        Ss    2011   0:00  \_ postgres: postgres smtp 127.0.0.1(33587) idle

postgres 20034  0.2  0.4  49252  4388 ?        Ss   03:15   1:18  \_ postgres: postgres smtp 127.0.0.1(58084) idle

postgres 20012  0.0  0.2  48796  2212 ?        Ss   13:20   0:00  \_ postgres: reporting reporting [local] idle  

postgres 20675  0.0  0.2  48796  2216 ?        Ss   13:26   0:00  \_ postgres: reporting reporting [local] idle  

postgres 21772  0.0  0.2  48796  2228 ?        Ss   13:33   0:00  \_ postgres: reporting reporting [local] idle  

postgres 21903 22.3  3.6  91332 37404 ?        Rs   13:35   0:00  \_ postgres: reporting reporting [local] SELECT

root      5014  0.2  3.0  61928 31088 ?        S     2011 348:36 /var/mdw/mdw.plx

root      5044  0.0  0.0   1796   232 ?        S     2011   0:09  \_ logger -p daemon.debug -t middleware[5014]

root      5460  0.0  0.0   2852    36 ?        Ss    2011   0:00  \_ /bin/bash /bin/DSL.sh eth7#REF_kVYnvPGZiR 60

root      1275  0.0  0.0   2692   156 ?        S    Jan11   0:00  |   \_ /usr/sbin/pppd-pppoe call REF_kVYnvPGZiR ipparam eth7#REF_k

root     27724  0.0  0.0   2852    36 ?        Ss    2011   0:01  \_ /bin/bash /bin/DSL.sh eth4#REF_zpchGYYQsu 5

root     18185  0.0  0.0   2692   148 ?        S    03:00   0:00      \_ /usr/sbin/pppd-pppoe call REF_zpchGYYQsu ipparam eth4#REF_z

root      5040  0.2  0.4   7768  4468 ?        S

Reply

0 UweT over 13 years ago

There is nothing unusual happening in the logs.

Currently we experiencing another 100% session again. It's one of a lot during a day.

Does that help?


USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND

(...)

root      4467  0.0  1.4  40500 14544 ?        Ss    2011 112:22 confd [master]

root      4468  0.0  0.0   1796   236 ?        S     2011   0:00  \_ logger -p daemon.debug -t confd[4467]

root      4907  0.0  0.6  39852  6492 ?        S     2011  13:49  \_ confd [listener]

root     19063  2.5  3.5  64584 36292 ?        S    13:10   0:38      \_ confd [worker[:P]rpc:webadmin]

root     21497  0.0  0.3   5820  3976 ?        Ss   13:32   0:00      |   \_ /usr/local/bin/traceable_system.plx /tmp/ts.19063.13263

root     21501  0.0  0.0   1832   492 ?        S    13:32   0:00      |   |   \_ /usr/bin/tail -n 10 -f /var/log/ips.log

root     21781  0.1  0.4   5952  4172 ?        Ss   13:34   0:00      |   \_ /usr/local/bin/traceable_system.plx /tmp/ts.19063.13263

root     21785  0.0  0.0   1832   500 ?        S    13:34   0:00      |   |   \_ /usr/bin/tail -n 10 -f /var/log/http.log

root     21904 33.3  0.0   2616   940 ?        R    13:35   0:00      |   \_ ps auxwf

root     20055  1.4  3.5  64388 36356 ?        S    13:22   0:12      \_ confd [worker[:P]rpc:webadmin]

root     21850  1.5  0.0      0     0 ?        Z    13:35   0:00      \_ [confd.plx] 

root     21851  1.4  0.0      0     0 ?        Z    13:35   0:00      \_ [confd.plx] 

root     21852  1.5  0.0      0     0 ?        Z    13:35   0:00      \_ [confd.plx] 

root      4533  0.0  0.2   7632  2588 ?        S     2011  30:45 /usr/local/bin/sysmond

root      4615  0.0  0.3  15424  3772 ?        S     2011   0:02 /var/aua/aua.bin

root     19064  0.0  0.0      0     0 ?        Z    13:10   0:00  \_ [aua.bin] 

root      4813  0.0  0.3  14056  3468 ?        S     2011   3:00 /usr/local/bin/notifier.plx -d

at        4821  0.0  0.0   2236    52 ?        Ss    2011   0:00 /usr/sbin/atd

postgres  4931  0.0  0.1  46772  1128 ?        S     2011   4:24 /usr/bin/postgres -D /var/storage/pgsql/data

postgres  4949  0.0  3.3  46860 34012 ?        Ss    2011  32:11  \_ postgres: writer process                    

postgres  4950  0.0  0.0  46772   352 ?        Ss    2011  33:31  \_ postgres: wal writer process                

postgres  4951  0.0  0.0  47044   784 ?        Ss    2011   7:43  \_ postgres: autovacuum launcher process       

postgres  4952  0.0  0.0   7356   700 ?        Ss    2011  17:39  \_ postgres: stats collector process           

postgres  5914  0.8  3.5  49648 36012 ?        Ss    2011 1038:45  \_ postgres: reporting reporting [local] idle  

postgres  6428  0.0  0.0  49184   868 ?        Ss    2011   0:00  \_ postgres: postgres smtp 127.0.0.1(33587) idle

postgres 20034  0.2  0.4  49252  4388 ?        Ss   03:15   1:18  \_ postgres: postgres smtp 127.0.0.1(58084) idle

postgres 20012  0.0  0.2  48796  2212 ?        Ss   13:20   0:00  \_ postgres: reporting reporting [local] idle  

postgres 20675  0.0  0.2  48796  2216 ?        Ss   13:26   0:00  \_ postgres: reporting reporting [local] idle  

postgres 21772  0.0  0.2  48796  2228 ?        Ss   13:33   0:00  \_ postgres: reporting reporting [local] idle  

postgres 21903 22.3  3.6  91332 37404 ?        Rs   13:35   0:00  \_ postgres: reporting reporting [local] SELECT

root      5014  0.2  3.0  61928 31088 ?        S     2011 348:36 /var/mdw/mdw.plx

root      5044  0.0  0.0   1796   232 ?        S     2011   0:09  \_ logger -p daemon.debug -t middleware[5014]

root      5460  0.0  0.0   2852    36 ?        Ss    2011   0:00  \_ /bin/bash /bin/DSL.sh eth7#REF_kVYnvPGZiR 60

root      1275  0.0  0.0   2692   156 ?        S    Jan11   0:00  |   \_ /usr/sbin/pppd-pppoe call REF_kVYnvPGZiR ipparam eth7#REF_k

root     27724  0.0  0.0   2852    36 ?        Ss    2011   0:01  \_ /bin/bash /bin/DSL.sh eth4#REF_zpchGYYQsu 5

root     18185  0.0  0.0   2692   148 ?        S    03:00   0:00      \_ /usr/sbin/pppd-pppoe call REF_zpchGYYQsu ipparam eth4#REF_z

root      5040  0.2  0.4   7768  4468 ?        S

Children

No Data