Guest User!

You are not Sophos Staff.

Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 27 replies
  • Subscribers 2 subscribers
  • Views 17606 views
  • Users 0 members are here
Options
Suggested
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?

UweT
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.
  • 0
    Check the System log to see if there are messages about problems with a PostgreSQL database.

    Cheers - Bob
  • 0
    No strange entries in the log.

    The CPU load issue happens around every 10 minutes today.
    The postgress circles around 80% even sometimes. Also the index.plx process takes up to 15% sometimes.

    Another example: 


    Tasks: 134 total,   2 running, 130 sleeping,   0 stopped,   2 zombie

    Cpu(s): 77.7%us, 11.3%sy,  0.0%ni,  0.0%id,  0.0%wa,  1.3%hi,  9.7%si,  0.0%st

    Mem:   1027696k total,   997548k used,    30148k free,     4568k buffers

    Swap:  1052248k total,   343228k used,   709020k free,   216108k cached

    

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

    26210 postgres  20   0  129m  74m  12m R 43.7 50.5   0:04.06 postgres

    24500 wwwrun    20   0 63480  53m 2360 S 16.9  5.4   0:23.81 index.plx

     4323 httpprox  20   0 1268m 200m 4452 S 13.6 20.0 435:17.48 httpproxy
  • 0
    Try the Selfmonitoring log. 

    Cheers - Bob

    Sorry for any short responses!  Posted from my iPhone.
  • 0
    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
  • 0
    Are there any maintenance commands for the reporting database?
  • 0
    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"


    have you contacted support?  Since you have an appliance you should be able to open a support ticket...[:)]
  • 0
    Since you have a comercial license, I agree that you likely will want to get Astaro Support involved.  First, you might want to try restoring a backup from before the problems began.  Next, schedule an after-hours upgrade to 8.3.

    Good luck!

    Cheers - Bob
  • 0
    I thought the same.

    Okay, this is the story:

    Yesterday afternoon already we did like an emergency update (after we informed every colleague inhouse). Also because v.8.203 promised better PostgreSQL performance and more HTTPproxy stability in its update description (aha?!).

    Now we are running on v.8.300. 

    This morning nobody who is using the webfilter proxy could access Internet pages. There was a user browser message popup which demanded to enter username and password for the proxy. Whatever you type in here it will not work, by the way!

    The webfilter live log came up with similar lines in in this Thread:
    https://community.sophos.com/products/unified-threat-management/astaroorg/f/55/t/44599

    Solution:
    Re-Configure the SSO to the AD:
    Definition & Users > Authentication Servers > Single Sign-On (SSO) > Active Directory SSO Username and Passwort Setting -> Apply

    I think some important connection information got lost when updating the Astaro so the AD access was kinda defect.

    Now everything seems to work smoothly... finally.

    * * *

    In German:
    https://community.sophos.com/products/unified-threat-management/astaroorg/f/55/t/44599

    * * *

    Thank you for your assistance!
    Uwe
  • 0
    Update:

    The 100% CPU load problem occurs again :-(


    top - 09:59:50 up 17:44,  1 user,  load average: 4.70, 4.00, 3.08
    Tasks: 132 total,   5 running, 125 sleeping,   0 stopped,   2 zombie
    Cpu(s): 71.6%us, 16.8%sy,  0.0%ni,  0.0%id,  0.0%wa,  1.7%hi,  9.9%si,  0.0%st
    Mem:   1027696k total,   941756k used,    85940k free,    21904k buffers
    Swap:  1052248k total,   224860k used,   827388k free,   246732k cached

      PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
     8913 postgres  20   0 50544 7504 5568 R 27.4  0.7   2:00.22 postgres
     6268 snort     19  -1  144m  86m 1224 R 23.8  8.6  15:41.25 snort_inline
    20421 wwwrun    20   0 99800  60m 1864 R 14.2  6.0   4:53.55 index.plx
    23027 httpprox  20   0 1204m 231m 5388 S 13.9 23.1  11:00.17 httpproxy
    (...)


    That is inacceptable.
  • 0 in reply to UweT
    I have deactivated the PostgreSQL process via SSH and that command:
    /etc/init.d/postgresql stop


    Although it shows peaks which I wonder about CPU % is around 40-50% then.


    top - 11:19:19 up 19:03,  1 user,  load average: 1.00, 1.88, 2.56
    Tasks: 122 total,   1 running, 119 sleeping,   0 stopped,   2 zombie
    Cpu(s): 15.6%us,  4.3%sy,  0.0%ni, 78.4%id,  0.3%wa,  0.3%hi,  1.0%si,  0.0%st
    Mem:   1027696k total,   943504k used,    84192k free,    47908k buffers
    Swap:  1052248k total,   252656k used,   799592k free,   321480k cached

      PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
    23027 httpprox  20   0 1210m 171m 5744 S  9.6 17.1  20:13.37 httpproxy
    26504 root      20   0 18812  10m 2992 S  5.0  1.1   0:01.56 websec-reporter
     5937 root      20   0  6964 2660 1104 S  2.0  0.3   6:41.79 syslog-ng
     6268 snort     19  -1  147m  91m 1208 S  2.0  9.1  22:07.55 snort_inline


    Webfilter Live log is still visible. Is this data being saved although i stopped the reporting service?

    By the way:
    What exactly does the PostgreSQL service do?


    * * *

    I wonder why this is happening: 68% CPU load for the httpproxy process:


    top - 11:22:02 up 19:06,  1 user,  load average: 2.69, 2.06, 2.49
    Tasks: 119 total,   2 running, 113 sleeping,   0 stopped,   4 zombie
    Cpu(s): 79.9%us, 11.2%sy,  0.3%ni,  0.0%id,  0.0%wa,  1.3%hi,  7.3%si,  0.0%st
    Mem:   1027696k total,   896484k used,   131212k free,    45472k buffers
    Swap:  1052248k total,   259548k used,   792700k free,   283564k cached

      PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
    23027 httpprox  20   0 1212m 167m 5868 S 58.8 16.7  20:42.19 httpproxy
    22879 wwwrun    20   0 69088  65m 8544 R 12.4  6.5   1:03.42 index.plx
     6268 snort     19  -1  148m  91m 1208 S  6.5  9.2  22:15.82 snort_inline
    26504 root      20   0 18812  10m 2992 S  5.9  1.1   0:08.75 websec-reporter
    22883 root      20   0 52484  23m 2800 S  4.9  2.3   0:25.23 confd.plx