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

[9.0044-33] Spikes of High CPU and memory

Hi All

I am using v9.0044-33 with UTM 120 rev 5. I am also using disk as part of the htp_local_db

It seems that the box is spiking on cpu and the memory is high .I have attached the relevant pic

As part of the troubleshooting I used perf top
Results 
  
   PerfTop:    1403 irqs/sec  kernel:22.1%  exact:  0.0% [1000Hz cycles],  (all, 2 CPUs)
-------------------------------------------------------------------------------------------------------------------------------------

    58.13%  pngquant                [.] 0x558a
     4.60%  libz.so.1.2.3           [.] longest_match
     2.41%  libpng12.so.0.31.0      [.] 0xf93c
     2.21%  [kernel]                [k] read_hpet
     1.40%  [unknown]               [.] 0x8050ed3
     1.07%  libz.so.1.2.3           [.] deflate_slow
     0.97%  libc-2.11.3.so          [.] msort_with_tmp
     0.93%  libcairo.so.2.10800.8   [.] unpremultiply_data
     0.68%  perf                    [.] 0x1e000
     0.59%  libc-2.11.3.so          [.] memcpy
     0.58%  libexpat.so.1.5.2       [.] 0xf9e6
     0.56%  libz.so.1.2.3           [.] fill_window
     0.48%  libfontconfig.so.1.3.0  [.] .L110
     0.47%  ld-2.11.3.so            [.] do_lookup_x
     0.39%  libc-2.11.3.so          [.] _int_malloc
     0.36%  ntpd                    [.] 0x1d013
     0.36%  libfreetype.so.6.3.18   [.] TT_RunIns
     0.33%  libfreetype.so.6.3.18   [.] 0x17a25
     0.33%  libfontconfig.so.1.3.0  [.] FcCompareFamily
     0.32%  libasapsdk.so           [.] 0x20c35
     0.29%  libc-2.11.3.so          [.] strstr
     0.27%  libz.so.1.2.3           [.] adler32
     0.24%  libperl.so              [.] 0x101f1f
     0.22%  libc-2.11.3.so          [.] __i686.get_pc_thunk.bx
     0.21%  postgres                [.] 0x2b7d4c
     0.20%  libpixman-1.so.0.16.0   [.] pixman_rasterize_edges
     0.20%  libc-2.11.3.so          [.] malloc
     0.20%  libc-2.11.3.so          [.] strcmp
     0.19%  [kernel]                [k] __kmalloc
     0.19%  libc-2.11.3.so          [.] __memset_ia32
     0.18%  libz.so.1.2.3           [.] inflate_fast
     0.18%  [kernel]                [k] unmap_vmas
     0.17%  [vdso]                  [.] 0x55576431
     0.16%  [kernel]                [k] __schedule
     0.16%  [kernel]                [k] page_fault
     0.16%  [kernel]                [k] ia32_sysenter_target
     0.16%  libpthread.so.0         [.] 0xefbf
     0.15%  [kernel]                [k] timerqueue_add
     0.14%  libc-2.11.3.so          [.] _int_free
     0.14%  libpixman-1.so.0.16.0   [.] pixman_edge_init
     0.14%  [kernel]                [k] _raw_spin_lock
     0.14%  [kernel]                [k] hpet_legacy_next_event
     0.14%  libc-2.11.3.so          [.] free


what is that process and why it's inroducing spikes to the box?

/root # top -b -n 1 | head -n 12  | tail -n 5
13298 root      39  19  3640 2080  632 R     90  0.1   0:00.73 pngquant
 3729 root      20   0 11528 4788 1772 S     12  0.2  91:02.42 selfmonng.plx
 4162 root      20   0 10140 6212 1668 S      9  0.3  23:28.03 dns-resolver.pl
13299 root      20   0  2808 1212  804 R      9  0.1   0:00.07 top
 4686 root      20   0 32940  11m 3028 S      4  0.6 163:57.32 ctasd


Memory is normal at the moment: 

/root # ps auxf | sort -nr -k 4 | head -5
810      28489  1.0 18.9 1205400 387520 ?      Ssl  12:18   3:07 /var/chroot-http/usr/bin/httpproxy -f -c /var/chroot-http -u httpproxy
root      4324  1.8 12.3 339384 253364 ?       Ssl  16:27   0:58 /usr/bin/cssd -d
snort     5520  0.3  5.5 385324 113612 ?       S


Most of the swap is allocated to the HTTP proxy (Run top then press 'O' (capital letter o) followed by 'p' then 'enter'. Now processes should be sorted by their swap usage.)

top - 17:22:28 up 3 days,  8:16,  1 user,  load average: 0.67, 1.22, 1.30
Tasks: 344 total,   1 running, 341 sleeping,   0 stopped,   2 zombie
Cpu(s):  2.4%us,  2.7%sy,  0.0%ni, 94.6%id,  0.3%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   2048484k total,  1666536k used,   381948k free,     3732k buffers
Swap:  1048572k total,   401552k used,   647020k free,   606832k cached

  PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  SWAP COMMAND
28489 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:36.18 799m httpproxy
28490 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:07.72 799m httpproxy
28491 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.74 799m httpproxy
28505 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.14 799m httpproxy
28508 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.75 799m httpproxy
28509 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.83 799m httpproxy
28510 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.50 799m httpproxy

28511 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.47 799m httpproxy
28512 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.43 799m httpproxy
28513 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.43 799m httpproxy
28514 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.41 799m httpproxy
28515 httpprox  20   0 1177m 377m 1312 S      0 18.9   0:00.45 799m httpproxy


There are  too many child-processes for httpproxy is this normal?


This thread was automatically locked due to age.
Parents
  • Strangely enough, checking the logs today via winSCP I can see that everything is set to 0 as if it's not logging anymore.I get the same result from webadmin>logging >everything is set to 0
    Latest entry on the confd log was 2012:11:27-16:28:03



    Confd-debug has messages like

    2012:11:27-16:25:47 ***** confd[3084]: D main::wakeup_subscribers:1130() => id="3100" severity="debug" sys="System" sub="confd" name="sending USR1 signal" client="screenmgr" pid="5297"
    2012:11:27-16:25:47 ***** confd[3084]: D main::wakeup_subscribers:1130() => id="3100" severity="debug" sys="System" sub="confd" name="sending USR1 signal" client="dns-resolver.plx" pid="4162"

    is this normal?

    Also System log

    2012:11:27-16:25:43 ***** syslog-ng[2671]: POLLERR occurred while idle; fd='139'
    2012:11:27-16:25:44 ***** dns-resolver[4162]: Updating REF_heqygyURNf :: streamcloud.mediacdn.com
    2012:11:27-16:25:47 ***** dns-resolver[4162]: No such IPv4 domain: imap-vdo.mx.aol.com (REF_SabkXLkTJK)
    2012:11:27-16:25:47 ***** dns-resolver[4162]: No such IPv6 domain: imap-vdo.mx.aol.com (REF_SabkXLkTJK)
    2012:11:27-16:25:47 ***** dns-resolver[4162]: Updating REF_SabkXLkTJK :: imap-vdo.mx.aol.com
    2012:11:27-16:26:01 ***** /usr/sbin/cron[3385]: (root) CMD (/sbin/audld.plx --nosys --trigger)
    2012:11:27-16:26:57 ***** dns-resolver[4162]: Updating REF_EwWPLqlCKU :: smtp.live.com
    2012:11:27-16:28:02 ***** dns-resolver[4162]: Updating REF_heqygyURNf :: streamcloud.mediacdn.com
    2012:11:27-16:28:04 ***** dns-resolver[4162]: No change to REF_EwWPLqlCKU :: smtp.live.com
    2012:11:27-16:28:17 ***** syslog-ng[2671]: Termination requested via signal, terminating;
    2012:11:27-16:28:17 ***** syslog-ng[2671]: syslog-ng shutting down; version='3.0.10'



    Nothing in fallback.log

    loginuser@*****:/var/mdw/scripts > ps -ef | grep postgres
    postgres  3604     1  0 Nov24 ?        00:00:42 /usr/pgsql84/bin/postgres -D /var/storage/pgsql/data
    postgres  3627  3604  0 Nov24 ?        00:02:18 postgres: writer process
    postgres  3628  3604  0 Nov24 ?        00:03:02 postgres: wal writer process
    postgres  3629  3604  0 Nov24 ?        00:01:40 postgres: autovacuum launcher process
    postgres  3630  3604  0 Nov24 ?        00:03:34 postgres: stats collector process
    postgres  4332  3604  0 Nov24 ?        00:00:59 postgres: postgres hotspot 127.0.0.1(43253) idle
    postgres  4508  3604  0 Nov24 ?        00:34:07 postgres: reporting reporting [local] idle
    postgres  4552  3604  0 Nov24 ?        00:00:44 postgres: postgres pop3 127.0.0.1(43269) idle
    postgres  5309  3604  0 Nov24 ?        00:00:00 postgres: postgres smtp 127.0.0.1(43285) idle
    postgres 13780  3604  0 07:13 ?        00:00:02 postgres: epp epp 127.0.0.1(34438) idle
    postgres 14854  3604  0 14:02 ?        00:00:00 postgres: postgres pop3 127.0.0.1(37309) idle
    100      14896 17906  0 14:03 pts/1    00:00:00 grep postgres
    postgres 17133  3604  0 Nov24 ?        00:00:00 postgres: postgres pop3 127.0.0.1(45728) idle
    postgres 18497  3604  0 Nov25 ?        00:00:00 postgres: postgres hotspot 127.0.0.1(35165) idle
    postgres 20879  3604  0 Nov24 ?        00:00:00 postgres: postgres smtp 127.0.0.1(45960) idle
    postgres 20882  3604  0 Nov24 ?        00:00:00 postgres: postgres pop3 127.0.0.1(45961) idle
    postgres 29745  3604  0 09:00 ?        00:01:15 postgres: postgres smtp 127.0.0.1(35131) idle
    postgres 32537  3604  0 Nov24 ?        00:00:00 postgres: postgres hotspot 127.0.0.1(44758) idle
    postgres 32681  3604  0 Nov24 ?        00:00:00 postgres: postgres hotspot 127.0.0.1(44778) idle


    Any ideas ?
Reply
  • Strangely enough, checking the logs today via winSCP I can see that everything is set to 0 as if it's not logging anymore.I get the same result from webadmin>logging >everything is set to 0
    Latest entry on the confd log was 2012:11:27-16:28:03



    Confd-debug has messages like

    2012:11:27-16:25:47 ***** confd[3084]: D main::wakeup_subscribers:1130() => id="3100" severity="debug" sys="System" sub="confd" name="sending USR1 signal" client="screenmgr" pid="5297"
    2012:11:27-16:25:47 ***** confd[3084]: D main::wakeup_subscribers:1130() => id="3100" severity="debug" sys="System" sub="confd" name="sending USR1 signal" client="dns-resolver.plx" pid="4162"

    is this normal?

    Also System log

    2012:11:27-16:25:43 ***** syslog-ng[2671]: POLLERR occurred while idle; fd='139'
    2012:11:27-16:25:44 ***** dns-resolver[4162]: Updating REF_heqygyURNf :: streamcloud.mediacdn.com
    2012:11:27-16:25:47 ***** dns-resolver[4162]: No such IPv4 domain: imap-vdo.mx.aol.com (REF_SabkXLkTJK)
    2012:11:27-16:25:47 ***** dns-resolver[4162]: No such IPv6 domain: imap-vdo.mx.aol.com (REF_SabkXLkTJK)
    2012:11:27-16:25:47 ***** dns-resolver[4162]: Updating REF_SabkXLkTJK :: imap-vdo.mx.aol.com
    2012:11:27-16:26:01 ***** /usr/sbin/cron[3385]: (root) CMD (/sbin/audld.plx --nosys --trigger)
    2012:11:27-16:26:57 ***** dns-resolver[4162]: Updating REF_EwWPLqlCKU :: smtp.live.com
    2012:11:27-16:28:02 ***** dns-resolver[4162]: Updating REF_heqygyURNf :: streamcloud.mediacdn.com
    2012:11:27-16:28:04 ***** dns-resolver[4162]: No change to REF_EwWPLqlCKU :: smtp.live.com
    2012:11:27-16:28:17 ***** syslog-ng[2671]: Termination requested via signal, terminating;
    2012:11:27-16:28:17 ***** syslog-ng[2671]: syslog-ng shutting down; version='3.0.10'



    Nothing in fallback.log

    loginuser@*****:/var/mdw/scripts > ps -ef | grep postgres
    postgres  3604     1  0 Nov24 ?        00:00:42 /usr/pgsql84/bin/postgres -D /var/storage/pgsql/data
    postgres  3627  3604  0 Nov24 ?        00:02:18 postgres: writer process
    postgres  3628  3604  0 Nov24 ?        00:03:02 postgres: wal writer process
    postgres  3629  3604  0 Nov24 ?        00:01:40 postgres: autovacuum launcher process
    postgres  3630  3604  0 Nov24 ?        00:03:34 postgres: stats collector process
    postgres  4332  3604  0 Nov24 ?        00:00:59 postgres: postgres hotspot 127.0.0.1(43253) idle
    postgres  4508  3604  0 Nov24 ?        00:34:07 postgres: reporting reporting [local] idle
    postgres  4552  3604  0 Nov24 ?        00:00:44 postgres: postgres pop3 127.0.0.1(43269) idle
    postgres  5309  3604  0 Nov24 ?        00:00:00 postgres: postgres smtp 127.0.0.1(43285) idle
    postgres 13780  3604  0 07:13 ?        00:00:02 postgres: epp epp 127.0.0.1(34438) idle
    postgres 14854  3604  0 14:02 ?        00:00:00 postgres: postgres pop3 127.0.0.1(37309) idle
    100      14896 17906  0 14:03 pts/1    00:00:00 grep postgres
    postgres 17133  3604  0 Nov24 ?        00:00:00 postgres: postgres pop3 127.0.0.1(45728) idle
    postgres 18497  3604  0 Nov25 ?        00:00:00 postgres: postgres hotspot 127.0.0.1(35165) idle
    postgres 20879  3604  0 Nov24 ?        00:00:00 postgres: postgres smtp 127.0.0.1(45960) idle
    postgres 20882  3604  0 Nov24 ?        00:00:00 postgres: postgres pop3 127.0.0.1(45961) idle
    postgres 29745  3604  0 09:00 ?        00:01:15 postgres: postgres smtp 127.0.0.1(35131) idle
    postgres 32537  3604  0 Nov24 ?        00:00:00 postgres: postgres hotspot 127.0.0.1(44758) idle
    postgres 32681  3604  0 Nov24 ?        00:00:00 postgres: postgres hotspot 127.0.0.1(44778) idle


    Any ideas ?
Children
No Data