Finding the source of disk write



  • Hi,

    I'm running pfSense in a virtual machine environment. The install is given its own partition as if it were a disk, and monitoring disk writes the the partition, it appears 200-500KB are being written once every 20s or so. How can I find out what is causing the writes from inside pfSense?

    Cheers,

    Yax



  • Probably monitoring stuff RRD and such. I run embedded installs usually though, those shouldn't do that.



  • Login to the console and drop to the shell (option 8).
    run top -a
    then press "m" to switch to toggle IO mode.



  • Hi,

    Cheers for the responses.

    top -a (m) shows that apinger is doing I/O most frequently, but that does not correlate with what I see when I run ls -lt in /var/log

    [2.0.1-RELEASE][root@pfsense]/var/log(9): ls -lt
    total 2010
    -rw-------  1 root  wheel  511488 Aug 21 12:24 filter.log
    -rw-------  1 root  wheel  512144 Aug 21 12:18 system.log
    -rw-r--r--  1 root  wheel   56028 Aug 21 12:15 lastlog
    -rw-------  1 root  wheel   65535 Aug 21 12:03 apinger.log
    -rw-------  1 root  wheel   65535 Aug 21 07:53 dhcpd.log
    -rw-r--r--  1 root  wheel    3573 Aug 16 23:43 lighttpd.error.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 openvpn.log
    -rw-------  1 root  wheel     568 Aug 11 12:47 userlog
    -rw-r--r--  1 root  wheel    5004 Aug 11 12:47 dmesg.boot
    -rw-------  1 root  wheel   65535 Aug 11 12:47 ipsec.log
    -rw-------  1 root  wheel   50688 Aug 11 12:47 l2tps.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 lighttpd.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 ntpd.log
    -rw-------  1 root  wheel   50688 Aug 11 12:47 poes.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 portalauth.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 ppp.log
    -rw-------  1 root  wheel   50688 Aug 11 12:47 pptps.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 relayd.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 slbd.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 vpn.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 wireless.log
    [2.0.1-RELEASE][root@pfsense]/var/log(10): 
    

    It appears filter.log is being written most frequently. It is not RRD graphs, because I have have disabled it. Is there any way to disable writes to filter.log? Most of what I see are lines like this:

    Aug 20 20:19:45 pfsense pf: 00:00:53.137812 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 12887, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 20 20:19:45 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 20 20:20:57 pfsense pf: 00:01:12.301496 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 20 20:20:57 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 20 20:21:50 pfsense pf: 00:00:52.695957 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 12905, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 20 20:21:50 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 20 20:23:03 pfsense pf: 00:01:12.743444 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 20 20:23:03 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 20 20:23:55 pfsense pf: 00:00:52.254273 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 12912, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 20 20:23:55 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 20 20:25:08 pfsense pf: 00:01:13.184872 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 20 20:25:08 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 20 20:26:00 pfsense pf: 00:00:51.812918 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 12919, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 20 20:26:00 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    
    

    But even this does not appear to be that frequent, or a few hundred KB of data.

    I am concerned because this is an SSD install in a virtual machine. While the SSD does have plenty of space, iostat from linux tells me pfSense has written far more data than anything else (approx 4GB, not sure if this is since last boot or not, if so, thats in 9 days).

    
    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
               0.00    0.00    0.63    0.00    0.02   99.35
    
    Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
    sda               0.40         0.36         6.17     312197    5323758
    sda1              0.00         0.00         0.00        732          0
    sda2              0.00         0.00         0.00       1712          9
    sda3              0.04         0.21         0.47     178966     409280
    sda4              0.31         0.08         5.40      68716    4664924
    sda5              0.03         0.07         0.29      61339     249545
    

    It might also explain the apparent increase CPU activity of the pfSense machine compared to the others:

    Name                                        ID   Mem VCPUs      State   Time(s)
    Domain-0                                     0 15267     8     r-----   6634.8
    jumpBox                                      1   512     1     -b----    804.3
    pfSense                                      2   256     1     -b---- 273107.2
    
    

    For completeness, a capture of top -a (m)

    last pid: 48049;  load averages:  0.00,  0.00,  0.00                                                                                                                                     up 9+23:48:08  12:34:35
    56 processes:  1 running, 55 sleeping
    CPU:  0.4% user,  0.0% nice,  0.0% system,  0.0% interrupt, 99.6% idle
    Mem: 65M Active, 21M Inact, 49M Wired, 396K Cache, 24M Buf, 92M Free
    Swap: 
    
      PID USERNAME   VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
    10979 root         10      4      0      1      0      1 100.00% /usr/local/sbin/apinger -c /var/etc/apinger.conf
    29304 root          6      6      0      0      0      0   0.00% /usr/local/sbin/openvpn --config /var/etc/openvpn/server1.conf
    47754 dhcpd         4      0      0      0      0      0   0.00% /usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dh
    24525 root          2      0      0      0      0      0   0.00% /usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0
    59643 root          2      0      0      0      0      0   0.00% /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfigurator.co
    15857 root          0      0      0      0      0      0   0.00% /usr/local/sbin/miniupnpd -f /var/etc/miniupnpd.conf -P /var/r
    50054 root          0      0      0      0      0      0   0.00% /usr/local/bin/php
    49606 root          0      0      0      0      0      0   0.00% /usr/local/bin/php
    49891 root          0      0      0      0      0      0   0.00% /usr/local/bin/php
    61667 root          0      0      0      0      0      0   0.00% /usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f /var/etc/
    10289 _ntp          0      0      0      0      0      0   0.00% ntpd: ntp engine (ntpd)
    10617 root          0      0      0      0      0      0   0.00% ntpd: [priv] (ntpd)
    43080 nobody        0      0      0      0      0      0   0.00% /usr/local/sbin/dnsmasq --local-ttl 1 --all-servers --rebind-l
    24722 root          0      0      0      0      0      0   0.00% logger -t pf -p local0.info
    56631 root          0      0      0      0      0      0   0.00% /usr/local/bin/rrdtool -
    32563 root          0      0      0      0      0      0   0.00% /usr/local/bin/minicron 240 /var/run/ping_hosts.pid /usr/local
    49536 root          0      0      0      0      0      0   0.00% /usr/sbin/cron -s
     9369 root          0      0      0      0      0      0   0.00% dhclient: em0 [priv] (dhclient)
    14920 _dhcp         0      0      0      0      0      0   0.00% dhclient: em0 (dhclient)
    30913 root          0      0      0      0      0      0   0.00% /usr/sbin/inetd -wW -R 0 -a 127.0.0.1 /var/etc/inetd.conf
      243 root          0      0      0      0      0      0   0.00% /usr/local/sbin/check_reload_status
    21031 root          1      0      0      0      0      0   0.00% top -a
    
    

    I'll be honest, I don't really know how to interpret the columns for the above, but I observed that apinger was frequently hitting 100%  in the PERCENT column.

    Regards,

    Yax



  • The apinger is the gateway monitoring, you can disable that under System::Routing per gateway.
    The other is the firewall logs under Status: System logs: Settings

    as far as I know, both should be on a ramdisk on the embedded install.



  • Hi,

    Cheers for the response. I disabled gateway monitoring and the amount being written appears to have reduced, but I don't see where in status->system logs->settings I can disable filter logging. (log packets blocked by the default rule was already unchecked) I can see an option which says "disable writing log files to local ram disk" which is unchecked. If I look in the firewall tab, it shows no entries "Last 0 firewall log entries. Max(50) " - I have not clicked the clear log button and I have no filter. top -a(m) now does not show any I/O activity at all, but I still have considerable writes to the disk:

    [root@domain0 ~]# iostat -p sda 10 | grep sda4
    sda4              0.31         0.07         5.38      68800    5108040
    sda4              0.00         0.00         0.00          0          0
    sda4              0.90         0.00        20.80          0        208
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.60         0.00        13.60          0        136
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.80         0.00        20.40          0        204
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.30         0.00         6.00          0         60
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              1.10         0.00        35.20          0        352
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              1.10         0.00        30.40          0        304
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.50         0.00        11.60          0        116
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.80         0.00        18.80          0        188
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.40         0.00        11.20          0        112
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.10         0.00         2.00          0         20
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              1.20         0.00        26.80          0        268
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    

    I am also still seeing writes to filter.log:

    [2.0.1-RELEASE][root@pfsense]/var/log(21): ls -lt
    total 2010
    -rw-------  1 root  wheel  511488 Aug 22 12:46 filter.log
    -rw-------  1 root  wheel  512144 Aug 22 12:21 system.log
    -rw-r--r--  1 root  wheel   56028 Aug 22 12:20 lastlog
    -rw-------  1 root  wheel   65535 Aug 22 12:13 apinger.log
    -rw-------  1 root  wheel   65535 Aug 22 10:58 dhcpd.log
    -rw-r--r--  1 root  wheel    4031 Aug 22 08:14 lighttpd.error.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 openvpn.log
    -rw-------  1 root  wheel     568 Aug 11 12:47 userlog
    -rw-r--r--  1 root  wheel    5004 Aug 11 12:47 dmesg.boot
    -rw-------  1 root  wheel   65535 Aug 11 12:47 ipsec.log
    -rw-------  1 root  wheel   50688 Aug 11 12:47 l2tps.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 lighttpd.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 ntpd.log
    -rw-------  1 root  wheel   50688 Aug 11 12:47 poes.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 portalauth.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 ppp.log
    -rw-------  1 root  wheel   50688 Aug 11 12:47 pptps.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 relayd.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 slbd.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 vpn.log
    -rw-------  1 root  wheel   65535 Aug 11 12:47 wireless.log
    
    

    Writes look like this:

    Aug 22 12:31:44 pfsense pf: 00:00:14.178134 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24167, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:31:44 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:33:35 pfsense pf: 00:01:51.261149 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:33:35 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:33:49 pfsense pf: 00:00:13.736819 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24188, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:33:49 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:35:41 pfsense pf: 00:01:51.702464 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:35:41 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:35:54 pfsense pf: 00:00:13.295136 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24194, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:35:54 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:37:46 pfsense pf: 00:01:52.144122 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:37:46 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:37:59 pfsense pf: 00:00:12.853590 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24199, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:37:59 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:39:51 pfsense pf: 00:01:52.585662 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:39:51 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:40:04 pfsense pf: 00:00:12.412132 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24206, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:40:04 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:41:57 pfsense pf: 00:01:53.027084 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:41:57 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:42:09 pfsense pf: 00:00:11.970590 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24227, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:42:09 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:44:02 pfsense pf: 00:01:53.468705 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:44:02 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:44:14 pfsense pf: 00:00:11.529038 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24234, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:44:14 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    Aug 22 12:46:08 pfsense pf: 00:01:53.910163 rule 36/8(ip-option): pass in on em1: (tos 0xc0, ttl 1, id 0, offset 0, flags [DF], proto IGMP (2), length 32, options (RA))
    Aug 22 12:46:08 pfsense pf:     0.0.0.0 > 224.0.0.1: igmp query v2
    Aug 22 12:46:19 pfsense pf: 00:00:11.087591 rule 35/8(ip-option): pass in on em0: (tos 0xc0, ttl 1, id 24241, offset 0, flags [DF], proto IGMP (2), length 36, options (RA))
    Aug 22 12:46:19 pfsense pf:     192.168.1.254 > 224.0.0.1: igmp query v3 [max resp time 24s]
    ength 32, options (RA))
    
    

    What does "rules 35/8" mean? All my filter rules have logging disabled.

    I am not running embedded install, but I am running full install.

    Cheers,

    Yax



  • The first thing top shows is average activity for each process, is that correct?

     top -I -a -mio -s40
    last pid: 23779;  load averages:  0.00,  0.00,  0.00                                                                                                                                                          up 1+22:02:42  11:56:09
    60 processes:  2 running, 58 sleeping
    CPU:     % user,     % nice,     % system,     % interrupt,     % idle
    Mem: 66M Active, 21M Inact, 47M Wired, 144K Cache, 24M Buf, 94M Free
    Swap:
    
      PID USERNAME   VCSW  IVCSW   READ  WRITE  FAULT  TOTAL PERCENT COMMAND
    30770 root      59296  22873      1      0      0      1   0.08% /usr/local/sbin/openvpn --config /var/etc/openvpn/server1.conf
    44997 root     166905  10202     81    156     67    304  23.90% /usr/local/sbin/lighttpd -f /var/etc/lighty-webConfigurator.co
    24801 root     165740    166      3      0     12     15   1.18% /usr/sbin/tcpdump -s 256 -v -l -n -e -ttt -i pflog0
    52956 root       1556   2218     13    294      1    308  24.21% /usr/local/bin/php
    21923 root       6656   5198      0      2      0      2   0.16% /usr/local/sbin/miniupnpd -f /var/etc/miniupnpd.conf -P /var/r
    52464 root       1083   1982     51     96      2    149  11.71% /usr/local/bin/php
    52603 root        711   1764     40    286      3    329  25.86% /usr/local/bin/php
      625 root       2444     28      0      7      0      7   0.55% /usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f /var/etc/
    43542 root       1384      6      0      2      0      2   0.16% /usr/local/bin/minicron 240 /var/run/ping_hosts.pid /usr/local
    15695 _dhcp      1461    525      0     12      0     12   0.94% dhclient: em0 (dhclient)
    33101 _dhcp       842    688      0     12      0     12   0.94% dhclient: em0 (dhclient)
      243 root        657    260      0      2      1      3   0.24% /usr/local/sbin/check_reload_status
    32986 root        184     70      1      0      0      1   0.08% /usr/sbin/inetd -wW -R 0 -a 127.0.0.1 /var/etc/inetd.conf
    49566 root         16    156      0     15      0     15   1.18% /usr/local/bin/php
    52249 root         16    142      0     15      0     15   1.18% /usr/local/bin/php
    45365 root         16     77      0     15      0     15   1.18% /usr/local/bin/php
    42213 nobody      120     44      0      1      0      1   0.08% /usr/local/sbin/dnsmasq --local-ttl 1 --all-servers --rebind-l
    44117 root         96      0      0      3      0      3   0.24% /usr/local/bin/minicron 3600 /var/run/expire_accounts.pid /etc
    50571 root         20     15     16      0      1     17   1.34% login [pam] (login)
     8660 root         22      9      0      2      0      2   0.16% /usr/sbin/sshd
    51262 root          8     10      2      0      1      3   0.24% -sh (sh)
    41571 root         57      4      0     53      0     53   4.17% /usr/local/sbin/dhcpleases -l /var/dhcpd/var/db/dhcpd.leases -
    44546 root          5      0      0      2      0      2   0.16% /usr/local/bin/minicron 86400 /var/run/update_alias_url_data.p
    46882 dhcpd         2      6      0      1      0      1   0.08% /usr/local/sbin/dhcpd -user dhcpd -group _dhcp -chroot /var/dh
    
    

    But if I leave that top update after 40s, top shows nothing. In fact, I cannot trace any activity via top now, even though

     iostat -I -d -x -z 30
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0      3090.0 88099.0 44093.0 1432770.0    0   1.5   0
    md0       54.0 15280.0   196.5 233674.5    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0  13.0     0.0   208.0    0   3.3   0
    md0        0.0   1.0     0.0    16.0    0   0.5   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   0.8   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   2.0     0.0    32.0    0   0.6   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   0.6   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0  51.0     0.0   634.0    0   5.1   0
    md0        0.0   2.0     0.0    28.0    0   0.4   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   0.7   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   5.0     0.0    80.0    0   1.1   0
    md0        0.0   1.0     0.0    16.0    0   0.4   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   3.0     0.0    48.0    0   1.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0  12.0     0.0   192.0    0   2.9   0
    md0        0.0   1.0     0.0    16.0    0   0.5   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   0.7   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   2.0     0.0    32.0    0   0.7   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   5.0     0.0    80.0    0   1.5   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   2.0     0.0    32.0    0   0.8   0
    md0        0.0   1.0     0.0    16.0    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   1.1   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   2.0     0.0    32.0    0   0.7   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0  15.0     0.0   240.0    0   3.9   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   9.0     0.0   144.0    0   2.5   0
    md0        0.0   1.0     0.0    16.0    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   3.0     0.0    48.0    0   0.6   0
    md0        0.0   1.0     0.0    16.0    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   3.0     0.0    48.0    0   0.8   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   0.7   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   2.0     0.0    32.0    0   0.6   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   3.0     0.0    48.0    0   0.7   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0  36.0     0.0   436.0    0   2.8   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0  15.0     0.0   212.0    0   3.1   0
    md0        0.0   1.0     0.0    16.0    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   7.0     0.0   112.0    0   1.5   0
    md0        0.0   1.0     0.0    16.0    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   8.0     0.0   128.0    0   1.7   0
    md0        0.0   1.0     0.0    16.0    0   0.0   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   3.0     0.0    48.0    0   0.9   0
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
                            extended device statistics
    device     r/i   w/i    kr/i    kw/i wait svc_t  %b
    ad0        0.0   1.0     0.0    16.0    0   0.7   0
    
    

    iostat shows considerable activity in some 30s intervals (and sometimes none). Does anybody have any idea what is generating this activity?



  • So a considerable source of disk writes were coming from igmp logging (which I wasn't able to stop through the web UI, but I have a workaround, details here http://forum.pfsense.org/index.php/topic,52887.0.html)
    However, a lot of disk writes are still coming from somewhere. I appreciate I could just install nanoBSD-VGA version, but I would actually rather find the source of disk writes. I also feel that there shouldn't be unexplained disk activity occurring on the system.

    Sep 14 08:14:50 pfsense dhclient: RENEW
    Sep 14 08:14:50 pfsense dhclient: Creating resolv.conf
    Sep 14 08:14:57 pfsense dhclient: RENEW
    Sep 14 08:14:57 pfsense dhclient: Creating resolv.conf
    Sep 14 08:44:20 pfsense dhclient: RENEW
    Sep 14 08:44:20 pfsense dhclient: Creating resolv.conf
    Sep 14 08:44:27 pfsense dhclient: RENEW
    Sep 14 08:44:27 pfsense dhclient: Creating resolv.conf
    Sep 14 09:13:50 pfsense dhclient: RENEW
    Sep 14 09:13:50 pfsense dhclient: Creating resolv.conf
    Sep 14 09:13:57 pfsense dhclient: RENEW
    Sep 14 09:13:57 pfsense dhclient: Creating resolv.conf
    Sep 14 09:43:20 pfsense dhclient: RENEW
    Sep 14 09:43:20 pfsense dhclient: Creating resolv.conf
    Sep 14 09:43:27 pfsense dhclient: RENEW
    Sep 14 09:43:27 pfsense dhclient: Creating resolv.conf
    Sep 14 10:12:50 pfsense dhclient: RENEW
    Sep 14 10:12:50 pfsense dhclient: Creating resolv.conf
    Sep 14 10:12:57 pfsense dhclient: RENEW
    Sep 14 10:12:57 pfsense dhclient: Creating resolv.conf
    Sep 14 10:42:20 pfsense dhclient: RENEW
    Sep 14 10:42:20 pfsense dhclient: Creating resolv.conf
    Sep 14 10:42:27 pfsense dhclient: RENEW
    Sep 14 10:42:27 pfsense dhclient: Creating resolv.conf
    Sep 14 11:07:52 pfsense sshd[43374]: Accepted keyboard-interactive/pam for root from #### port 37867 ssh2
    Sep 14 11:11:51 pfsense dhclient: RENEW
    Sep 14 11:11:51 pfsense dhclient: Creating resolv.conf
    Sep 14 11:11:57 pfsense dhclient: RENEW
    Sep 14 11:11:57 pfsense dhclient: Creating resolv.conf
    Sep 14 11:14:28 pfsense php: /index.php: Successful webConfigurator login for user ####
    Sep 14 11:14:28 pfsense php: /index.php: Successful webConfigurator login for user ####
    Sep 14 11:28:18 pfsense sshd[47927]: Accepted keyboard-interactive/pam for root from #### port 37956 ssh2
    
    

    The above are contents of system.log - based on this, I am confident this is not being written to frequently enough to show the disk activity I am seeing.

    [2.0.1-RELEASE][root@pfsense]/var/log(8): ls -lt; date
    total 1482
    -rw-------  1 root  wheel  512144 Sep 14 11:28 system.log
    -rw-r--r--  1 root  wheel   56028 Sep 14 11:28 lastlog
    -rw-------  1 root  wheel   65535 Sep 14 07:46 dhcpd.log
    -rw-r--r--  1 root  wheel    3075 Sep 14 00:49 lighttpd.error.log
    -rw-------  1 root  wheel   65535 Sep 11 08:06 openvpn.log
    -rw-------  1 root  wheel   65535 Sep  8 02:17 apinger.log
    -rw-------  1 root  wheel     568 Sep  6 12:54 userlog
    -rw-r--r--  1 root  wheel    5004 Sep  6 12:54 dmesg.boot
    -rw-------  1 root  wheel   65535 Sep  6 12:54 ipsec.log
    -rw-------  1 root  wheel   50688 Sep  6 12:54 l2tps.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 lighttpd.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 ntpd.log
    -rw-------  1 root  wheel   50688 Sep  6 12:54 poes.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 portalauth.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 ppp.log
    -rw-------  1 root  wheel   50688 Sep  6 12:54 pptps.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 relayd.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 slbd.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 vpn.log
    -rw-------  1 root  wheel   65535 Sep  6 12:54 wireless.log
    Fri Sep 14 11:34:25 BST 2012
    [2.0.1-RELEASE][root@pfsense]/var/log(9): 
    
    

    But this is the sort of activity I see at 30s intervals:

    [root@host ~]# iostat -p /dev/sda 30 | grep sda4
    sda4              0.14         0.10         2.70      69728    1840648
    sda4              0.10         0.00         1.33          0         40
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.40         0.00         8.53          0        256
    sda4              0.00         0.00         0.00          0          0
    sda4              0.13         0.00         2.67          0         80
    sda4              0.53         0.00        21.07          0        632
    sda4              0.00         0.00         0.00          0          0
    sda4              0.33         0.00         8.80          0        264
    sda4              0.17         0.00         3.87          0        116
    sda4              0.00         0.00         0.00          0          0
    sda4              0.40         0.00         8.53          0        256
    sda4              0.00         0.00         0.00          0          0
    sda4              0.03         0.00         0.67          0         20
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.00         0.00         0.00          0          0
    sda4              0.23         0.67         4.93         20        148
    
    

    Which is still far too high in my opinion, particularly when I cannot identify the source.

    I would be grateful if any further assistance could be provided in helping me to identify the cause.



  • I've found the following 0 byte files that are being written pretty often (no idea what with, or why the writes are so large)

    [2.0.1-RELEASE][root@pfsense]/var/log(33): find / -type f | xargs ls -lt | head -n 2
    -rw-r--r--  1 root      wheel           0 Sep 19 17:15 /tmp/tmpHOSTS
    -rw-r--r--  1 root      wheel           0 Sep 19 17:15 /var/db/currentipsecpinghosts
    [2.0.1-RELEASE][root@pfsense]/var/log(34): 
    
    

    How can I stop these files being written?

    Cheers,

    Yax


Locked