Nano slow to mount Read-Only
-
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
-
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)
-
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
-
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
-
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)
-
[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. ;)
-
Can you reproduce it on other cards? Or other systems?
-
Also while it's "stuck", press ctrl-T, see what gets printed.
-
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. -
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
-
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
-
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
-
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
-
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
-
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
-
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.
-
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
-
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
-
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>