Nano slow to mount Read-Only


  • Netgate Administrator

    I am seeing big delays in writing any config changes because (it seems) there is a problem re-mounting the filesystem RO. Both 32 and 64bit. The problem is negated by setting the filesystem permanently RW. It seems exactly like the issue that was seen in the 2.1Betas. Or was is 2.0Beta?  :-
    I don't see anyone else complaining though which seems odd.

    Steve


  • Rebel Alliance Developer Netgate

    How slow is slow? That hasn't been a problem in a very long time.

    I can't seem to reproduce any slowness on a current 2.2 snap. Make sure the CPU isn't maxed out from something else (e.g. check_reload_status)


  • Netgate Administrator

    I am not running the latest snapshot but it has been the case for all the snaps I've tried (not that many) over the last 6 weeks or so. I'll update and check.
    When making a config change in the webgui the page waits to reload for, maybe, 20s. I've not timed it but it was long enough that making several changes became completely impractical. I'll run a test.
    The box is doing almost nothing else. There is nothing behind it.

    I seem to recall, somewhere in the back of my fading memory, a test that showed exactly what the machine was waiting for when this was previously an issue. Certainly can't recall what that was though.  ::)

    Steve


  • Netgate Administrator

    Ok so I'm running:

    [2.2-ALPHA][root@pfsense.localdomain]/root(5): uname -a
    FreeBSD pfsense.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #58 e852cd6(HEAD)-dirty: Wed May 21 19:20:17 CDT 2014     root@pf22-amd64-snap:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10  amd64
    
    

    This is a 1GB image running from a 4GB CF card.

    Perhaps relevant is that I updated to 64bit from 32bit.

    Saving a config change in the webgui takes ~27s. Running rc.conf_mount_ro takes ~25s.

    I'll try the latest snap.

    Steve


  • Rebel Alliance Developer Netgate

    you could run it through truss -f, perhaps.

    [2.2-ALPHA][root@alix]/root(8): time /etc/rc.conf_mount_rw
    0.499u 0.104s 0:00.71 83.0%     3688+308k 0+12io 0pf+0w
    [2.2-ALPHA][root@alix]/root(9): time /etc/rc.conf_mount_ro
    0.517u 0.200s 0:02.11 33.6%     3147+283k 0+655io 0pf+0w
    

    That's as slow as I've seen it, and it's still not as slow as it was before (e.g. +30s)


  • Netgate Administrator

    [2.2-ALPHA][root@pfsense.localdomain]/root(1): time /etc/rc.conf_mount_rw
    0.067u 0.025s 0:00.60 13.3%	4087+332k 0+30io 0pf+0w
    [2.2-ALPHA][root@pfsense.localdomain]/root(2): time /etc/rc.conf_mount_ro
    0.053u 2.325s 0:25.36 9.3%	177+183k 0+704io 0pf+0w
    
    

    More accurate than the Android stopwatch.  ;)


  • Rebel Alliance Developer Netgate

    Can you reproduce it on other cards? Or other systems?


  • Rebel Alliance Developer Netgate

    Also while it's "stuck", press ctrl-T, see what gets printed.


  • Netgate Administrator

    Pretty sure I tried a different card but let me check for sure. Same behaviour on the two systems I tried.
    Ran truss -f, wall of text! Output attached.

    mountrw3.txt


  • Netgate Administrator

    Ctrl-T shows:

    [2.2-ALPHA][root@pfsense.localdomain]/tmp(19): /etc/rc.conf_mount_ro
    load: 0.07  cmd: mount 87137 [biowr] 0.36r 0.00u 0.00s 0% 2068k
    load: 0.07  cmd: mount 87137 [biowr] 4.31r 0.00u 0.23s 2% 2068k
    load: 0.07  cmd: mount 87137 [biowr] 5.10r 0.00u 0.28s 2% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 5.88r 0.00u 0.28s 2% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 6.79r 0.00u 0.31s 2% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 8.09r 0.00u 0.32s 1% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 9.04r 0.00u 0.56s 4% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 9.98r 0.00u 0.65s 4% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 10.91r 0.00u 0.69s 4% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 11.48r 0.00u 0.81s 5% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 11.72r 0.00u 0.81s 5% 2068k
    load: 0.06  cmd: mount 87137 [biowr] 11.91r 0.00u 0.81s 4% 2068k
    load: 0.06  cmd: mount 87137 [running] 12.08r 0.00u 0.88s 5% 2068k
    load: 0.06  cmd: mount 87137 [running] 13.73r 0.00u 1.40s 10% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 14.42r 0.00u 1.57s 10% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 15.26r 0.00u 1.63s 10% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 16.04r 0.00u 1.63s 9% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 16.92r 0.00u 1.73s 9% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 17.66r 0.00u 1.79s 9% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 18.39r 0.00u 1.84s 9% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 19.17r 0.00u 1.86s 8% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 20.22r 0.00u 1.90s 8% 2068k
    load: 0.05  cmd: mount 87137 [running] 21.02r 0.00u 1.90s 7% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 22.14r 0.00u 2.01s 7% 2068k
    load: 0.05  cmd: mount 87137 [biowr] 23.01r 0.00u 2.02s 7% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 23.81r 0.00u 2.15s 8% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 24.60r 0.00u 2.27s 8% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 25.39r 0.00u 2.29s 8% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 26.20r 0.00u 2.29s 7% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 27.01r 0.00u 2.30s 7% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 27.77r 0.00u 2.30s 6% 2068k
    load: 0.04  cmd: mount 87137 [biowr] 28.75r 0.00u 2.30s 5% 2068k
    
    

  • Netgate Administrator

    Ok. I could be mistaken on this. Different system, different card, much older snap:

    [2.2-ALPHA][root@testbox.localdomain]/root(1): uname -a
    FreeBSD testbox.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #0 fde2f5e(HEAD)-dirty: Sat Apr 12 14:04:38 CDT 2014     root@builder-10-0-b3-i386:/usr/obj.pfSense/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    [2.2-ALPHA][root@testbox.localdomain]/root(2): time /etc/rc.conf_mount_rw
    0.150u 0.075s 0:03.79 5.8%      3447+428k 1768+35io 0pf+0w
    [2.2-ALPHA][root@testbox.localdomain]/root(3): time /etc/rc.conf_mount_ro
    0.091u 0.010s 0:00.12 83.3%     4595+431k 0+29io 0pf+0w
    
    

    I'll try updating both.

    Steve


  • Netgate Administrator

    Or maybe not. Same box but updated to latest snap:

    [2.2-ALPHA][root@testbox.localdomain]/root(12): uname -a
    FreeBSD testbox.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #28 e852cd6(HEAD)-dirty: Tue May 27 11:01:10 CDT 2014     root@pf22-i386-snap:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    [2.2-ALPHA][root@testbox.localdomain]/root(13): time /etc/rc.conf_mount_rw
    0.080u 0.048s 0:00.41 29.2%     3347+293k 0+30io 0pf+0w
    [2.2-ALPHA][root@testbox.localdomain]/root(14): time /etc/rc.conf_mount_ro
    0.085u 1.249s 0:22.28 5.9%      348+187k 0+589io 0pf+0w
    

    However on this latest snap I have check_reload_status eating 100% CPU so this may not be a fair test.  ;)

    Steve


  • Netgate Administrator

    Latest snap on the original box seems to show no delay:

    
    [2.2-ALPHA][root@pfsense.localdomain]/root(4): uname -a
    FreeBSD pfsense.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #73 e852cd6(HEAD)-dirty: Tue May 27 10:51:27 CDT 2014     root@pf22-amd64-snap:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10  amd64
    [2.2-ALPHA][root@pfsense.localdomain]/root(5): time /etc/rc.conf_mount_rw
    0.063u 0.015s 0:00.07 100.0%    4668+360k 0+18io 0pf+0w
    [2.2-ALPHA][root@pfsense.localdomain]/root(6): time /etc/rc.conf_mount_ro
    0.047u 0.031s 0:00.07 100.0%    4668+360k 0+18io 0pf+0w
    
    

    Steve


  • Netgate Administrator

    Hmm, so it showed no delay imediately after the update but this morning:

    [2.2-ALPHA][root@pfsense.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.076u 0.016s 0:00.59 13.5%	4087+332k 0+30io 0pf+0w
    [2.2-ALPHA][root@pfsense.localdomain]/root(4): time /etc/rc.conf_mount_ro
    load: 0.00  cmd: mount 79567 [biowr] 11.22r 0.00u 0.55s 3% 2068k
    load: 0.00  cmd: mount 79567 [biowr] 12.15r 0.00u 0.68s 4% 2068k
    load: 0.00  cmd: mount 79567 [biowr] 13.14r 0.00u 0.70s 4% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 14.33r 0.00u 0.82s 4% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 15.35r 0.00u 0.86s 4% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 16.29r 0.00u 0.93s 4% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 17.45r 0.00u 0.97s 4% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 17.91r 0.00u 1.02s 5% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 18.92r 0.00u 1.07s 5% 2068k
    load: 0.08  cmd: mount 79567 [biowr] 19.90r 0.00u 1.11s 5% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 20.88r 0.00u 1.14s 4% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 21.89r 0.00u 1.20s 4% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 22.82r 0.00u 1.23s 4% 2068k
    load: 0.07  cmd: mount 79567 [running] 23.80r 0.00u 1.35s 5% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 24.80r 0.00u 1.39s 4% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 26.03r 0.00u 1.48s 5% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 27.01r 0.00u 1.50s 4% 2068k
    load: 0.07  cmd: mount 79567 [biowr] 27.96r 0.00u 1.56s 5% 2068k
    0.040u 1.638s 0:29.00 5.7%	219+174k 0+643io 0pf+0w
    [2.2-ALPHA][root@pfsense.localdomain]/root(5): uname -a
    FreeBSD pfsense.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #73 e852cd6(HEAD)-dirty: Tue May 27 10:51:27 CDT 2014     root@pf22-amd64-snap:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10  amd64
    
    

    The only thing I have done since then is removed a static DHCP lease. Doesn't seem too arduous.  ;)

    Since nobody else has complained about this it's likely a problem with my particular setup so this thread is more for my own documentation that anything else. Of course any suggestions are always welcome.

    Steve


  • Netgate Administrator

    Upgraded to latest snap. Imediately after upgrade, longest delay yet:

    
    [2.2-ALPHA][root@pfsense.localdomain]/root(2): uname -a
    FreeBSD pfsense.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #74 e852cd6(HEAD)-dirty: Tue May 27 19:39:44 CDT 2014     root@pf22-amd64-snap:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10  amd64
    [2.2-ALPHA][root@pfsense.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.070u 0.023s 0:00.58 15.5%	3996+323k 0+30io 0pf+0w
    [2.2-ALPHA][root@pfsense.localdomain]/root(4): time /etc/rc.conf_mount_ro
    0.063u 3.462s 0:41.48 8.4%	126+175k 0+1244io 0pf+0w
    
    

    No CPU load at that time.

    Time to swap out the CF card.

    Steve



  • @stephenw10:

    Upgraded to latest snap. Imediately after upgrade, longest delay yet:

    No CPU load at that time.

    Time to swap out the CF card.

    Steve

    I first thought you may be seeing the built-in ECC kicking in as the wear leveling exercises different blocks, but that seems excessive.


  • Netgate Administrator

    This only happens when the card is re-mounted as read-only. If it were ware levelling of some sort I would expect to see it even with the card permanently mounted RW.

    Steve


  • Netgate Administrator

    Ok so with i386 snapshots back to full function I had a chance to try a different card. Result, it definitely seems card dependent.
    Original CF card that was previously slow:

    
    [2.2-ALPHA][root@alphatestbox.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.104u 0.024s 0:00.41 29.2%     3106+274k 0+30io 0pf+0w
    [2.2-ALPHA][root@alphatestbox.localdomain]/root(4): time /etc/rc.conf_mount_ro
    0.086u 1.261s 0:28.76 4.6%      343+184k 0+639io 0pf+0w
    [2.2-ALPHA][root@alphatestbox.localdomain]/root(5): uname -a
    FreeBSD alphatestbox.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #51 e852cd6(HEAD)-dirty: Thu Jun  5 07:33:46 CDT 2014     root@pf22-i386-snap:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    [2.2-ALPHA][root@alphatestbox.localdomain]/conf(21): dmesg | grep ada0
    ada0 at ata0 bus 0 scbus0 target 0 lun 0
    ada0: <cf 20100226="">ATA-7 device
    ada0: Serial Number 20110613 00000F5C
    ada0: 16.700MB/s transfers (PIO4, PIO 512bytes)
    ada0: 3831MB (7847280 512 byte sectors: 16H 63S/T 7785C)
    ada0: Previously was known as ad0</cf> 
    

    Different CF card but identical otherwise:

    
    2.2-ALPHA][root@alphatestbox.localdomain]/root(1): uname -a
    FreeBSD alphatestbox.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #51 e852cd6(HEAD)-dirty: Thu Jun  5 07:33:46 CDT 2014     root@pf22-i386-snap:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    [2.2-ALPHA][root@alphatestbox.localdomain]/root(2): dmesg|grep ada0
    ada0 at ata0 bus 0 scbus0 target 0 lun 0
    ada0: <sony 20071016="" ncfd2g="">CFA-6 device
    ada0: Serial Number 4120382194200660000C
    ada0: 16.700MB/s transfers (PIO4, PIO 512bytes)
    ada0: 1911MB (3915072 512 byte sectors: 16H 63S/T 3884C)
    ada0: Previously was known as ad0
    [2.2-ALPHA][root@alphatestbox.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.106u 0.015s 0:00.07 157.1%	4165+337k 0+30io 0pf+0w
    [2.2-ALPHA][root@alphatestbox.localdomain]/root(4): time /etc/rc.conf_mount_ro
    0.100u 0.109s 0:06.40 3.1%	2156+228k 0+470io 0pf+0w</sony> 
    

    So a lot faster, 6s vs 28s, but still a very noticeable delay doing a series of config changes in the GUI like the initial wizard for example.

    I think I have some more cards I can try. Also try 64bit now the snapshots have restarted.

    Steve


  • Netgate Administrator

    Some more data points:

    Unbranded 2GB Card 41s

    [2.2-ALPHA][root@pfSense.localdomain]/root(1): uname -a
    FreeBSD pfSense.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #51 e852cd6(HEAD)-dirty: Thu Jun  5 07:33:46 CDT 2014     root@pf22-i386-snap:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    [2.2-ALPHA][root@pfSense.localdomain]/root(2): dmesg|grep ada0
    ada0 at ata0 bus 0 scbus0 target 0 lun 0
    ada0: < 20071116> ATA-0uhub1: 2 ports with 2 removable, self powered
    ada0: Serial Number ASWIN 00003322
    ada0: 16.700MB/s transfers (PIO4, PIO 512bytes)
    ada0: 1935MB (3964464 512 byte sectors: 16H 63S/T 3933C)
    ada0: Previously was known as ad0
    [2.2-ALPHA][root@pfSense.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.076u 0.045s 0:00.08 137.5%    3907+328k 0+31io 0pf+0w
    [2.2-ALPHA][root@pfSense.localdomain]/root(4): time /etc/rc.conf_mount_ro
    0.098u 0.107s 0:41.54 0.4%      2119+235k 0+466io 0pf+0w
    

    Transcend 4GB Card 19s

    [2.2-ALPHA][root@pfSense.localdomain]/root(1): uname -a
    FreeBSD pfSense.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #51 e852cd6(HEAD)-dirty: Thu Jun  5 07:33:46 CDT 2014     root@pf22-i386-snap:/usr/obj.i386/usr/pfSensesrc/src/sys/pfSense_wrap.10.i386  i386
    [2.2-ALPHA][root@pfSense.localdomain]/root(2): dmesg|grep ada0
    ada0 at ata0 bus 0 scbus0 target 0 lun 0
    ada0: <ts4gcf133 20100804=""> ATA-7uhub1: 2 ports with 2 removable, self powered
    ada0: Serial Number 20101112 C5130A66
    ada0: 16.700MB/s transfers (PIO4, PIO 512bytes)
    ada0: 3823MB (7831152 512 byte sectors: 16H 63S/T 7769C)
    ada0: Previously was known as ad0
    [2.2-ALPHA][root@pfSense.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.089u 0.040s 0:00.59 20.3%     3581+301k 0+30io 0pf+0w
    [2.2-ALPHA][root@pfSense.localdomain]/root(4): time /etc/rc.conf_mount_ro
    0.095u 1.175s 0:18.85 6.6%      341+182k 0+441io 0pf+0w</ts4gcf133>
    

    Kodak 1GB Card 64bit 12s- and that is a _muc_h faster machine.

    [2.2-ALPHA][root@xtm5.localdomain]/root(1): uname -a
    FreeBSD xtm5.localdomain 10.0-STABLE FreeBSD 10.0-STABLE #1 e852cd6(HEAD)-dirty: Fri Jun  6 02:39:07 CDT 2014     root@pf22-amd64-snap:/usr/obj.amd64/usr/pfSensesrc/src/sys/pfSense_SMP.10  amd64
    [2.2-ALPHA][root@xtm5.localdomain]/root(2): dmesg|grep ada0
    ada0 at ata0 bus 0 scbus0 target 0 lun 0
    ada0: <kodak ata="" flash="" v1.01=""> CFA-0 device
    ada0: Serial Number 11015111099199091128
    ada0: 16.700MB/s transfers (PIO4, PIO 2048bytes)
    ada0: 983MB (2014992 512 byte sectors: 16H 63S/T 1999C)
    ada0: Previously was known as ad0
    [2.2-ALPHA][root@xtm5.localdomain]/root(3): time /etc/rc.conf_mount_rw
    0.051u 0.034s 0:00.14 57.1%     4085+315k 0+30io 0pf+0w
    [2.2-ALPHA][root@xtm5.localdomain]/root(4): time /etc/rc.conf_mount_ro
    0.049u 0.347s 0:12.09 3.1%      794+199k 0+628io 0pf+0w</kodak>
    

    Steve



  • SanDisk 4G (i think the Ultra 30MB/s)

    [2.2-ALPHA][root@pfsense.ramos.local]/root(33): dmesg | grep ada0
    ada0 at ata2 bus 0 scbus1 target 1 lun 0
    ada0: <sandisk sdcfx-004g="" hdx="" 6.03="">CFA-0 device
    ada0: Serial Number ADZ1007XXXXXXXX
    ada0: 150.000MB/s transfers (SATA, UDMA4, PIO 512bytes)
    ada0: 3815MB (7813120 512 byte sectors: 16H 63S/T 7751C)
    ada0: Previously was known as ad5
    [2.2-ALPHA][root@pfsense.ramos.local]/root(34): time /etc/rc.conf_mount_rw
    0.102u 0.023s 0:00.12 100.0%    4357+336k 0+18io 0pf+0w
    [2.2-ALPHA][root@pfsense.ramos.local]/root(35): time /etc/rc.conf_mount_ro
    0.089u 0.037s 0:00.13 84.6%     5050+389k 0+18io 0pf+0w</sandisk> 
    

  • Netgate Administrator

    0.1s is more like it.  :)
    I guess you're using a SATA interface, the transfer speed is a lot higher.

    Steve



  • @stephenw10:

    0.1s is more like it.  :)
    I guess you're using a SATA interface, the transfer speed is a lot higher.

    Steve

    Sata interface with a Marvel converter to Compact Flash.


Log in to reply