Nano slow to mount Read-Only
-
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>
-
0.1s is more like it. :)
I guess you're using a SATA interface, the transfer speed is a lot higher.Steve
-
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.