Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 5 replies
  • Subscribers 3 subscribers
  • Views 5413 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

httpproxy high CPU on 9.5

DCALS

Hi,

Running UTM 9.510-5. (Home edition, Intel E5700 3GHz CPU, 4GB RAM)

I'm seeing the httpproxy service consume 100% of available CPU on a fairly regular basis (twice this week alone).  Have searched this forum and google but nothing seems relevant to version 9.5.  I'm not running endpoint protection on any clients either, and have only got single AV scan configured.  I'm sure my CPU/RAM is sufficient as this is just a home network with a total of about 20 devices vying for internet access.  Never had any issues on a Draytek with web filtering enabled, so 99% sure I'm not overloading the UTM! ;-)

Disabling web filtering and then turning it back on seems to fix it until the next time.

Ive included a top and copy of the CPU graph for reference.

I'm not sure where to start troubleshooting this as I'm not that familiar with the Sophos product.  Can anyone help with some pointers to get me started?

TIA

D

top - 16:20:38 up 1 day,  7:05,  1 user,  load average: 42.68, 47.55, 49.01

Tasks: 160 total,   3 running, 154 sleeping,   0 stopped,   3 zombie

Cpu(s): 98.3%us,  1.3%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.3%si,  0.0%st

Mem:   4019960k total,  3871276k used,   148684k free,    11712k buffers

top - 16:29:37 up 1 day,  7:14,  1 user,  load average: 52.47, 51.16, 50.20

Tasks: 162 total,   3 running, 155 sleeping,   0 stopped,   4 zombie

Cpu(s): 98.7%us,  1.2%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.2%si,  0.0%st

Mem:   4019960k total,  3866540k used,   153420k free,     8156k buffers

Swap:  4194300k total,   635092k used,  3559208k free,  1494540k cached

 

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

 5176 httpprox  20   0 2104m 1.5g 3736 S    198 39.4 491:16.20 httpproxy                                          

  434 root      20   0 20712  13m 2860 S      0  0.3   0:12.75 pfilter-reporte                                    

  449 root      20   0  4304  740  664 S      0  0.0   0:16.64 waf-reporter                                       

  675 afcd      19  -1 58628  24m 3116 S      0  0.6   0:03.03 afcd                                               

 3970 root      20   0 14148 4444 2192 S      0  0.1   5:30.39 selfmonng.plx                                      

 4418 root      20   0  152m 117m 1168 S      0  3.0   1:24.78 named                                              

 5128 root      20   0 70712   9m 1544 S      0  0.3   1:22.42 smtpd.bin                                          

    1 root      20   0  3976  504  484 S      0  0.0   0:00.96 init                                               

    2 root      20   0     0    0    0 S      0  0.0   0:00.00 kthreadd                                           

    3 root      20   0     0    0    0 S      0  0.0   0:12.23 ksoftirqd/0                                        

    5 root       0 -20     0    0    0 S      0  0.0   0:00.00 kworker/0:0H                                       

    7 root      RT   0     0    0    0 S      0  0.0   0:00.11 migration/0                                        

    8 root      20   0     0    0    0 S      0  0.0   0:01.77 rcu_bh                                             

    9 root      20   0     0    0    0 S      0  0.0   0:16.90 rcu_sched                                          

   10 root      RT   0     0    0    0 S      0  0.0   0:00.08 migration/1                                        

   11 root      20   0     0    0    0 S      0  0.0   0:01.39 ksoftirqd/1                                        

   12 root      20   0     0    0    0 S      0  0.0   0:00.00 kworker/1:0                                        

   13 root       0 -20     0    0    0 S      0  0.0   0:00.00 kworker/1:0H                                       

   14 root       0 -20     0    0    0 S      0  0.0   0:00.00 khelper                                            

  123 root       0 -20     0    0    0 S      0  0.0   0:00.00 writeback                                          

  126 root       0 -20     0    0    0 S      0  0.0   0:00.00 bioset                                             

  127 root       0 -20     0    0    0 S      0  0.0   0:00.00 crypto                                             

  129 root       0 -20     0    0    0 S      0  0.0   0:00.00 kblockd                                            

  244 root      20   0     0    0    0 S      0  0.0   0:00.00 khubd                                              

  252 root       0 -20     0    0    0 S      0  0.0   0:00.00 edac-poller                                        

  258 root      20   0     0    0    0 S      0  0.0   0:31.38 kworker/0:1                                        

  375 root      20   0     0    0    0 S      0  0.0   0:04.90 kswapd0                                            

  435 root      20   0 32128  19m 2920 S      0  0.5   0:00.97 admin-reporter.                                    

  436 root      20   0 39372 1256 1024 S      0  0.0   0:00.23 vpn-reporter.pl                                    

  437 root      20   0 30656 1764 1316 S      0  0.0   0:00.51 websec-reporter                                    

  438 root      20   0 18740  10m 2776 S      0  0.3   0:00.30 mailsec-reporte                                    

  440 root      39  19     0    0    0 S      0  0.0   0:05.98 khugepaged                                         

  441 root      20   0     0    0    0 S      0  0.0   0:00.00 fsnotify_mark                                      

  447 root      20   0 18896  10m 2556 S      0  0.3   0:00.37 ips-reporter.pl                                    

  448 root      20   0 30536 1312 1032 S      0  0.0   0:00.11 websec-reporter                                    

  452 postgres  20   0  594m  14m  10m S      0  0.4   0:00.75 postgres                                           

  455 postgres  20   0  590m 4556 2940 S      0  0.1   0:00.00 postgres                                           

  465 postgres  20   0  590m 5460 3644 S      0  0.1   0:00.00 postgres                                           

  489 root      20   0     0    0    0 S      0  0.0   0:02.00 kworker/u8:2                                       

  504 postgres  20   0  590m 5592 3640 S      0  0.1   0:00.00 postgres                                           

  695 postfix   20   0  8472 1996 1824 S      0  0.0   0:00.12 pickup                                             

  696 postfix   20   0  8636 2060 1924 S      0  0.1   0:00.16 qmgr                                               

  702 postfix   20   0  8480 2048 1720 S      0  0.1   0:00.12 tlsmgr                                             

 1088 root       0 -20     0    0    0 S      0  0.0   0:00.00 deferwq                                            

 1093 root      20   0     0    0    0 S      0  0.0   0:00.02 kworker/0:2                                        

 1171 root       0 -20     0    0    0 S      0  0.0   0:00.00 ata_sff                                            

 1188 root      20   0     0    0    0 S      0  0.0   0:00.00 scsi_eh_0                                          

 1191 root      20   0     0    0    0 S      0  0.0   0:00.00 scsi_eh_1                                          

 1204 root      20   0     0    0    0 S      0  0.0   0:00.02 scsi_eh_2                                          

 1207 root      20   0     0    0    0 S      0  0.0   0:00.00 scsi_eh_3                                          

 1642 root       0 -20     0    0    0 S      0  0.0   0:06.46 kworker/1:1H                                       

 1732 root       0 -20     0    0    0 S      0  0.0   0:05.60 kworker/0:1H                                       

 2353 root      20   0     0    0    0 S      0  0.0   0:23.20 kworker/1:2                                        

 2406 root      20   0     0    0    0 S      0  0.0   0:03.49 jbd2/sda6-8                                        

 2407 root       0 -20     0    0    0 S      0  0.0   0:00.00 ext4-rsv-conver                                    

 2469 root      16  -4  4628  360  360 S      0  0.0   0:00.05 udevd                                              

 2779 root      20   0     0    0    0 S      0  0.0   0:00.00 jbd2/sda1-8                                        

 2780 root       0 -20     0    0    0 S      0  0.0   0:00.00 ext4-rsv-conver                                    

 2781 root      20   0     0    0    0 S      0  0.0   0:09.17 jbd2/sda5-8                                        

 2782 root       0 -20     0    0    0 S      0  0.0   0:00.00 ext4-rsv-conver                                    

 2783 root      20   0     0    0    0 S      0  0.0   0:04.23 jbd2/sda7-8                                        

 2784 root       0 -20     0    0    0 S      0  0.0   0:00.00 ext4-rsv-conver                                    

 2785 root      20   0     0    0    0 S      0  0.0   0:00.09 jbd2/sda8-8                                        



This thread was automatically locked due to age.
Parents
  • 0

    Hi D and welcome to the UTM Community!

    Which CPU and how much RAM are you using?

    What do you see in the Up2Date messages log on Saturday when the jump to 100% started?

    Cheers - Bob

     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • 0 in reply to BAlfson

    Hi Bob, thanks for responding.

    Intel E5700 3GHz CPU (Dual core), 4GB RAM

    So it looks like there was a couple of updates starting at 12:43pm for aptp and savi then no activity until 2:53pm which was about when I rebooted it.  According to the CPU graphs, the 100% spike started at 1pm.  Does any of this look relevant? I'm not sure that it does, however you've pointed me in the right direction, need to look through some other logs.

    Log crossing that time frame:

    2018:11:04-12:43:08 utm audld[23958]: no HA system or cluster node
2018:11:04-12:43:08 utm audld[23958]: Starting Up2Date Package Downloader
2018:11:04-12:43:19 utm audld[23958]: patch up2date possible
2018:11:04-12:43:30 utm audld[23958]: id="3701" severity="info" sys="system" sub="up2date" name="Authentication successful"
2018:11:04-12:53:09 utm audld[24682]: no HA system or cluster node
2018:11:04-12:53:09 utm audld[24682]: Starting Up2Date Package Downloader
2018:11:04-12:53:20 utm audld[24682]: patch up2date possible
2018:11:04-12:53:32 utm audld[24682]: id="3701" severity="info" sys="system" sub="up2date" name="Authentication successful"
2018:11:04-12:53:34 utm audld[24682]: id="3707" severity="info" sys="system" sub="up2date" name="Successfully synchronized fileset" status="success" action="download" package="savi"
2018:11:04-12:53:40 utm audld[24682]: id="3707" severity="info" sys="system" sub="up2date" name="Successfully synchronized fileset" status="success" action="download" package="aptp"
2018:11:04-12:53:47 utm auisys[24751]: no HA system or cluster node
2018:11:04-12:53:47 utm auisys[24751]: waiting for db_verify to return (30 seconds max)
2018:11:04-12:53:54 utm auisys[24751]: not cleaning /var/up2date/sys-install in --nosys mode
2018:11:04-12:53:54 utm auisys[24751]: removing '/var/up2date/appctrl43-install'
2018:11:04-12:53:54 utm auisys[24751]: removing '/var/up2date/aptp-install'
2018:11:04-12:53:54 utm auisys[24751]: removing '/var/up2date/geoip-install'
2018:11:04-12:53:54 utm auisys[24751]: removing '/var/up2date/ipsbundle2-install'
2018:11:04-12:53:55 utm auisys[24751]: removing '/var/up2date/savi-install'
2018:11:04-12:53:55 utm auisys[24751]: Starting Up2Date Package Installer
2018:11:04-12:53:55 utm auisys[24751]: No suitable packages of type <appctrl43> found, skipping
2018:11:04-12:53:55 utm auisys[24751]: No suitable packages of type <geoip> found, skipping
2018:11:04-12:53:55 utm auisys[24751]: No suitable packages of type <ipsbundle2> found, skipping
2018:11:04-12:53:55 utm auisys[24751]: Install u2d packages <aptp>
2018:11:04-12:53:55 utm auisys[24751]: Starting installing up2date packages for type 'aptp'
2018:11:04-12:53:55 utm auisys[24751]: Installing up2date package: /var/up2date/aptp/u2d-aptp-9.31452-31453.patch.tgz.gpg
2018:11:04-12:53:56 utm auisys[24751]: Verifying up2date package signature
2018:11:04-12:54:00 utm auisys[24751]: Unpacking installation instructions
2018:11:04-12:54:02 utm auisys[24751]: parsing installation instructions
2018:11:04-12:54:04 utm auisys[24751]: This is a patch. Setting required_version to 9.31452
2018:11:04-12:54:04 utm auisys[24751]: Unpacking up2date package container
2018:11:04-12:54:06 utm auisys[24751]: Running pre-installation checks
2018:11:04-12:54:08 utm auisys[24751]: Starting up2date package installation
2018:11:04-12:54:42 utm auisys[24751]: Still waiting for process '/bin/rpm' (pid=24833, timeout 300 seconds, 270 remaining)
2018:11:04-12:55:12 utm auisys[24751]: id="371Z" severity="info" sys="system" sub="up2date" name="Successfully installed Up2Date package" status="success" action="install" package_version="9.31453" package="aptp"
2018:11:04-12:55:12 utm auisys[24751]: [INFO-306] New Pattern Up2Dates installed
2018:11:04-12:55:12 utm auisys[24751]: Install u2d packages <savi>
2018:11:04-12:55:12 utm auisys[24751]: Starting installing up2date packages for type 'savi'
2018:11:04-12:55:13 utm auisys[24751]: Installing up2date package: /var/up2date/savi/u2d-savi-9.13294-13295.patch.tgz.gpg
2018:11:04-12:55:13 utm auisys[24751]: Verifying up2date package signature
2018:11:04-12:55:13 utm auisys[24751]: Unpacking installation instructions
2018:11:04-12:55:13 utm auisys[24751]: parsing installation instructions
2018:11:04-12:55:13 utm auisys[24751]: This is a patch. Setting required_version to 9.13294
2018:11:04-12:55:13 utm auisys[24751]: Unpacking up2date package container
2018:11:04-12:55:13 utm auisys[24751]: Running pre-installation checks
2018:11:04-12:55:15 utm auisys[24751]: Starting up2date package installation
2018:11:04-12:55:54 utm auisys[24751]: id="371Z" severity="info" sys="system" sub="up2date" name="Successfully installed Up2Date package" status="success" action="install" package_version="9.13295" package="savi"
2018:11:04-12:55:54 utm auisys[24751]: [INFO-306] New Pattern Up2Dates installed
2018:11:04-12:55:55 utm auisys[24751]: Up2Date Package Installer finished, exiting
2018:11:04-12:55:55 utm auisys[24751]: id="3716" severity="info" sys="system" sub="up2date" name="Up2Date Package Installer finished, exiting"
2018:11:04-14:53:10 utm audld[32653]: no HA system or cluster node

     

    Thanks

    D

  • 0 in reply to DCALS

    hmmm.. there were a lot of packet drops in the IPS logs so I've increased the value of queue_length from 2048 to 3072 (baby steps!)

    Not sure if this was a factor but we'll see...

    D

  • 0 in reply to DCALS

    My guess is that it's cssd reconfiguring the database of antivirus rules after the savi installation.  You might try increasing RAM to 8GB.

    Please let us know when you find the solution.

    Cheers - Bob

     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • 0 in reply to BAlfson

    I'm having the same issue. My CPU spikes look just like yours, except I have 12gb of RAM in my UTM. As with you, toggling Web Protection seems to temporarily fix the issue. My RAM never spikes only the CPU. Sophos support blamed this on the up-to-date definition checks being to frequent. I turned them down and it seemed to fix the problem for a couple months, but now today the same thing happened. I'm still looking for a solution.

Reply
  • 0 in reply to BAlfson

    I'm having the same issue. My CPU spikes look just like yours, except I have 12gb of RAM in my UTM. As with you, toggling Web Protection seems to temporarily fix the issue. My RAM never spikes only the CPU. Sophos support blamed this on the up-to-date definition checks being to frequent. I turned them down and it seemed to fix the problem for a couple months, but now today the same thing happened. I'm still looking for a solution.

Children
No Data
Unfiltered HTML