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.
  • Thanks Bill

    Let's see if that will work [:)]
  • Now that I've seen this for myself, I wonder if this isn't related to cssd...

    Sorry, I am not familiar with cssd problem. I know it always uses some CPU cycles (which has always bugged me).

    Thanks Bill

    Let's see if that will work [:)]

    Sure no problem. Keep in mind guys this is just a bandaid  and a bad one at that.  The memory leak will have to be fixed by astaro. 

    Core daemons like proxy and IPS need a rewrite in my opinion.
  • Let me add my "Thanks!" to Bill for posting those (meant to include that in my last post).

    Bill, I didn't mean cssd, I meant the daemon that gets categorization info for the HTTP Proxy.  And, I didn't mean to imply that I thought this was an error.  Maybe httpd writes that info to the cache after it gets "old" - like not used in the last five minutes.

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • clearly there is something wrong on 9.004-33. Look at my latest swap  figures 
    http (no db cashing)



     PID USER      PR  NI  VIRT  RES  SHR S   %CPU %MEM    TIME+  SWAP COMMAND                                                        
     4648 httpprox  20   0 1412m 187m  548 S      0  9.4   0:47.90 1.2g httpproxy                                                       
     4649 httpprox  20   0 1412m 187m  548 S      0  9.4   0:57.63 1.2g httpproxy                                                       
     4650 httpprox  20   0 1412m 187m  548 S      0  9.4   0:05.95 1.2g httpproxy                                                       
     4861 httpprox  20   0 1412m 187m  548 S      0  9.4   0:01.30 1.2g httpproxy                                                       
     4902 httpprox  20   0 1412m 187m  548 S      0  9.4   0:08.55 1.2g httpproxy                                                       
     4903 httpprox  20   0 1412m 187m  548 S      0  9.4   0:12.13 1.2g httpproxy                                                       
     4904 httpprox  20   0 1412m 187m  548 S      0  9.4   0:10.00 1.2g httpproxy                                                       
     4905 httpprox  20   0 1412m 187m  548 S      0  9.4   0:15.78 1.2g httpproxy                                                       
     4906 httpprox  20   0 1412m 187m  548 S      0  9.4   0:08.75 1.2g httpproxy                                                       
     4907 httpprox  20   0 1412m 187m  548 S      0  9.4   0:05.24 1.2g httpproxy                                                       
     4908 httpprox  20   0 1412m 187m  548 S      0  9.4   0:08.03 1.2g httpproxy                                                       
     4909 httpprox  20   0 1412m 187m  548 S      0  9.4   0:05.20 1.2g httpproxy                                                       
     4910 httpprox  20   0 1412m 187m  548 S      0  9.4   0:08.96 1.2g httpproxy                                                       
     4911 httpprox  20   0 1412m 187m  548 S      0  9.4   0:05.19 1.2g httpproxy                                                       
     4912 httpprox  20   0 1412m 187m  548 S      0  9.4   0:07.06 1.2g httpproxy


    I've noticed also that my pop3 proxy restarts at least once a day so i restarted ctasd and I get no more pop3 proxy restarts. Also executing the scripts for proxy restart and swap reclaim the system looks better now (really high again but at least better than 100%)

    root # free -m
                 total       used       free     shared    buffers     cached
    Mem:          2000       1269        731          0          9        458
    -/+ buffers/cache:        800       1199
    Swap:         1023        736        287

  • Sorry, I am not familiar with cssd problem. I know it always uses some CPU cycles (which has always bugged me).

    Sure no problem. Keep in mind guys this is just a bandaid  and a bad one at that.  The memory leak will have to be fixed by astaro.

    Core daemons like proxy and IPS need a rewrite in my opinion.


    Agreed...they have added feature after feature with little regard to the realities of the lack of code quality....

    Owner:  Emmanuel Technology Consulting

    http://etc-md.com

    Former Sophos SG(Astaro) advocate/researcher/Silver Partner

    PfSense w/Suricata, ntopng, 

    Other addons to follow


  • Also, you won't get any emails about the proxy restart. Probably appending --sendmail  at the end of each command will send you the mails but I have never tried it. The restart should be logged in your system log.
    Regards
    Bill


    Can you tell me which log file is system log. I restarted proxy manually but i don't see that in my /var/log/system.log


  • Can you tell me which log file is system log. I restarted proxy manually but i don't see that in my /var/log/system.log


    Check the web filtering log (http proxy)

    Sent from my iPhone using Astaro.org
  • I agree, v9 is a resource hog.  Mine is virtual with ESXi 5

    6GB RAM assigned, 65% in use. 295 IP in use, but a lot of those are just server or temp assigned to WiFi etc.  (Around 100 actual staff).

    47% used by HTTP proxy.  Be nice if we could set a limit?

    I agree the feature add vs code optimisation has suffered, I wouldn't mind if next major version just concentrated on optimisation of speed and resource usage.
  • Check the web filtering log (http proxy)

    Sent from my iPhone using Astaro.org


    Yes I looked at web filtering log (http proxy) and there is line written in that moment when i run /var/mdw/scripts/httpproxy restart :

    2012:12:14-13:42:29 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="epoll_loop" file="epoll.c" line="796" message="starting exit cleanup"
    2012:12:14-13:42:29 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="scan_exit" file="scanner.c" line="374" message="scanner subsystem shutting down"
    2012:12:14-13:42:31 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="scan_exit" file="scanner.c" line="380" message="scanner subsystem shut down"
    2012:12:14-13:42:31 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="epoll_exit" file="epoll.c" line="622" message="epoll subsystem shutting down"
    2012:12:14-13:42:31 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="epoll_exit" file="epoll.c" line="637" message="epoll subsystem shut down"
    2012:12:14-13:42:31 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="disk_cache_exit" file="diskcache.c" line="44" message="writing cache index"
    2012:12:14-13:42:31 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="disk_cache_exit" file="diskcache.c" line="46" message="writing cache index done"
    2012:12:14-13:42:31 mail httpproxy[15928]: id="0003" severity="info" sys="SecureWeb" sub="http" request="(nil)" function="main" file="httpproxy.c" line="333" message="shutdown finished, exiting"



    So I edited etc/crontab with

    30 5 * * *     root    /var/mdw/scripts/httpproxy restart
    35 5 * * *     root    sync; echo 3 > /proc/sys/vm/drop_caches

    and tomorrow will show me if it is working [:)]
  • I just didn't to wait till morning and made some jobs to be executed during day.

    etc/crontab with line works:

    30 15 * * *     root    /var/mdw/scripts/httpproxy restart

    and web filtering log (http proxy) shows it.

    I didn't find anything about cache drop in http log file. 

    35 15 * * *     root    sync; echo 3 > /proc/sys/vm/drop_caches


    But my internet now is working super fast comparing to last week [:)]