SEO

>>>>> "rd" == RD Thrush <rd@thrush.com> writes:
rd> [ snip ]
rd> Entering ddb always show one process WAITing on "no_fltram5"
rd> [ snip ]

"no_fltram5" occurs in /usr/src/sys/uvm/uvm_fault.c. Noticing that
UVMHIST captures some further stats, I've got another hang with some
additional details. The full report has been added to the kernel/5777
[1] problem report including ddb session and dmesg.

[1] <http://cvs.openbsd.org/cgi-bin/query-pr-wrapper?full=yes&textonly=yes&numbers=5777>

I've appended the additional UVMHIST info related to the last hang as
well as the custom kernel dmesg. I've googled the web as well as the
MARC archives and have not found illumination.

I would greatly appreciate an explanation / analysis of this hang. It
seems odd that I'm the only one that has noticed the problem.



ddb> call uvm_hist(0)
1207516830.227265 uvm_swap_io#1655298: called!
1207516830.227270 uvm_swap_io#1655298: <- called, startslot=14894, npages=1, flags=1048576
1207516830.227342 uvm_swap_io#1655298: about to start io: data = 0xd51a3000 blkno = 0x1d170, bcount = 4096
1207516830.227347 swstrategy#251527: called!
1207516830.227351 swstrategy#251527: read: mapoff=1 bn=0x1d168 bcount=4096
1207516830.228215 uvm_swap_io#1655289: <- done (sync) result=0
1207516830.229246 uvm_swap_io#1655290: <- done (sync) result=0
1207516830.230705 uvm_swap_io#1655299: called!
1207516830.230708 uvm_swap_io#1655299: <- called, startslot=39200, npages=1, flags=1048576
1207516830.230777 uvm_swap_io#1655299: about to start io: data = 0xd519d000 blkno = 0x4c900, bcount = 4096
1207516830.230784 swstrategy#251528: called!
1207516830.230789 swstrategy#251528: read: mapoff=1 bn=0x4c8f8 bcount=4096
1207516830.230948 uvm_swap_io#1655300: called!
1207516830.230953 uvm_swap_io#1655300: <- called, startslot=24848, npages=1, flags=1048576
1207516830.231027 uvm_swap_io#1655300: about to start io: data = 0xd51a0000 blkno = 0x30880, bcount = 4096
1207516830.231034 swstrategy#251529: called!
1207516830.231040 swstrategy#251529: read: mapoff=1 bn=0x30878 bcount=4096
1207516830.231333 uvm_swap_io#1655301: called!
1207516830.231338 uvm_swap_io#1655301: <- called, startslot=27374, npages=1, flags=1048576
1207516830.231412 uvm_swap_io#1655301: about to start io: data = 0xd51a7000 blkno = 0x35770, bcount = 4096
1207516830.231417 swstrategy#251530: called!
1207516830.231421 swstrategy#251530: read: mapoff=1 bn=0x35768 bcount=4096
1207516830.231875 uvm_swap_io#1655302: called!
1207516830.231878 uvm_swap_io#1655302: <- called, startslot=7498, npages=1, flags=1048576
1207516830.231955 uvm_swap_io#1655302: about to start io: data = 0xd51a8000 blkno = 0xea50, bcount = 4096
1207516830.231960 swstrategy#251531: called!
1207516830.231965 swstrategy#251531: read: mapoff=1 bn=0xea48 bcount=4096
1207516830.232112 uvm_swap_io#1655303: called!
1207516830.232116 uvm_swap_io#1655303: <- called, startslot=63848, npages=1, flags=1048576
1207516830.232194 uvm_swap_io#1655303: about to start io: data = 0xd51a9000 blkno = 0x7cb40, bcount = 4096
1207516830.232201 swstrategy#251532: called!
1207516830.232205 swstrategy#251532: read: mapoff=1 bn=0x7cb38 bcount=4096
1207516830.234190 uvm_swap_io#1655304: called!
1207516830.234194 uvm_swap_io#1655304: <- called, startslot=71542, npages=1, flags=1048576
1207516830.234263 uvm_swap_io#1655304: about to start io: data = 0xd51aa000 blkno = 0x8bbb0, bcount = 4096
1207516830.234270 swstrategy#251533: called!
1207516830.234275 swstrategy#251533: read: mapoff=1 bn=0x8bba8 bcount=4096
1207516830.246969 uvm_swap_io#1655291: <- done (sync) result=0
1207516830.247892 uvm_swap_io#1655295: <- done (sync) result=0
1207516830.248309 uvm_swap_io#1655305: called!
1207516830.248312 uvm_swap_io#1655305: <- called, startslot=5561, npages=1, flags=1048576
1207516830.248390 uvm_swap_io#1655305: about to start io: data = 0xd519e000 blkno = 0xadc8, bcount = 4096
1207516830.248397 swstrategy#251534: called!
1207516830.248403 swstrategy#251534: read: mapoff=1 bn=0xadc0 bcount=4096
1207516830.249584 uvm_swap_io#1655306: called!
1207516830.249589 uvm_swap_io#1655306: <- called, startslot=73877, npages=1, flags=1048576
1207516830.249665 uvm_swap_io#1655306: about to start io: data = 0xd51a6000 blkno = 0x904a8, bcount = 4096
1207516830.249672 swstrategy#251535: called!
1207516830.249676 swstrategy#251535: read: mapoff=1 bn=0x904a0 bcount=4096
1207516830.253161 uvm_swap_io#1655302: <- done (sync) result=0
1207516830.253411 uvm_swap_io#1655307: called!
1207516830.253415 uvm_swap_io#1655307: <- called, startslot=13643, npages=1, flags=1048576
1207516830.253483 uvm_swap_io#1655307: about to start io: data = 0xd51a8000 blkno = 0x1aa58, bcount = 4096
1207516830.253488 swstrategy#251536: called!
1207516830.253492 swstrategy#251536: read: mapoff=1 bn=0x1aa50 bcount=4096
1207516830.256857 uvm_swap_io#1655298: <- done (sync) result=0
1207516830.261220 uvm_swap_io#1655294: <- done (sync) result=0
1207516830.270233 uvm_swap_io#1655300: <- done (sync) result=0
1207516830.270612 uvm_swap_io#1655308: called!
1207516830.270616 uvm_swap_io#1655308: <- called, startslot=14458, npages=1, flags=1048576
1207516830.270702 uvm_swap_io#1655308: about to start io: data = 0xd51a0000 blkno = 0x1c3d0, bcount = 4096
1207516830.270708 swstrategy#251537: called!
1207516830.270712 swstrategy#251537: read: mapoff=1 bn=0x1c3c8 bcount=4096
1207516830.270742 uvm_pageout#0: <<WOKE UP>>
1207516830.270749 uvm_pageout#0: free/ftarg=168/170, inact/itarg=35704/35864
1207516830.270756 uvmpd_scan#1267: called!
1207516830.270762 uvmpd_scan#1267: free 168 < target 170: swapout
1207516830.272328 uvmpd_scan#1267: starting 'free' loop
1207516830.272334 uvmpd_scan_inactive#2132: called!
1207516830.272379 uvm_pager_put#740220: called!
1207516830.272968 uvm_swap_io#1655309: called!
1207516830.272971 uvm_swap_io#1655309: <- called, startslot=16003, npages=1, flags=1048576
1207516830.273047 uvm_swap_io#1655309: about to start io: data = 0xd51a5000 blkno = 0x1f418, bcount = 4096
1207516830.273053 swstrategy#251538: called!
1207516830.273058 swstrategy#251538: read: mapoff=1 bn=0x1f410 bcount=4096
1207516830.276791 uvm_swap_io#1655301: <- done (sync) result=0
1207516830.281982 uvm_swap_io#1655292: <- done (sync) result=0
1207516830.284190 uvm_swap_io#1655297: <- done (sync) result=0
1207516830.284459 uvm_swap_io#1655310: called!
1207516830.284465 uvm_swap_io#1655310: <- called, startslot=6168, npages=1, flags=1048576
1207516830.284550 uvm_swap_io#1655310: about to start io: data = 0xd519f000 blkno = 0xc0c0, bcount = 4096
1207516830.284557 swstrategy#251539: called!
1207516830.284562 swstrategy#251539: read: mapoff=1 bn=0xc0b8 bcount=4096
1207516830.286056 uvm_swap_io#1655299: <- done (sync) result=0
1207516830.288343 uvm_swap_io#1655293: <- done (sync) result=0
1207516830.298067 uvm_swap_io#1655296: <- done (sync) result=0
1207516830.298479 uvm_swap_io#1655311: called!
1207516830.298484 uvm_swap_io#1655311: <- called, startslot=41129, npages=1, flags=1048576
1207516830.298570 uvm_swap_io#1655311: about to start io: data = 0xd519d000 blkno = 0x50548, bcount = 4096
1207516830.298578 swstrategy#251540: called!
1207516830.298582 swstrategy#251540: read: mapoff=1 bn=0x50540 bcount=4096
1207516830.307858 uvm_swap_io#1655303: <- done (sync) result=0
1207516830.311960 uvm_swap_io#1655304: <- done (sync) result=0
1207516830.317578 uvm_swap_io#1655306: <- done (sync) result=0
1207516830.335302 uvm_swap_io#1655305: <- done (sync) result=0
1207516830.346458 uvm_swap_io#1655310: <- done (sync) result=0
1207516830.354115 uvm_swap_io#1655307: <- done (sync) result=0
1207516830.358183 uvm_swap_io#1655308: <- done (sync) result=0
1207516830.359701 uvm_swap_io#1655309: <- done (sync) result=0
1207516830.368171 uvm_swap_io#1655311: <- done (sync) result=0
1207516833.611734 uvm_fault#14742554: narrow=1, back=3, forw=0, startva=0xcfbdc000
1207516833.611739 uvm_fault#14742554: entry=0xd6742010, amap=0xd69df3ac, obj=0x0
1207516833.611742 amap_lookups#14350961: called!
1207516833.611746 amap_lookups#14350961: slot=12, npages=4, nslot=16
1207516833.611751 amap_lookups#14350961: <- done
1207516833.611756 uvm_fault#14742554: shadowed=1, will_get=0
1207516833.611760 uvm_fault#14742554: case 1 fault: anon=0xd67add00
1207516833.611763 uvmfault_anonget#1169761: called!
1207516833.611768 uvmfault_anonget#1169761: <- OK
1207516833.611773 uvm_fault#14742554: MAPPING: anon: pm=0xd6a97e1c, va=0xcfbdf000, pg=0xd1072500
1207516842.742577 uvm_km_alloc1#1091227: called!
1207516842.742583 uvm_km_alloc1#1091227: (map=0xd118dc00, size=0x4000)
1207516842.742590 uvm_map#3447358: called!
1207516842.742595 uvm_map#3447358: (map=0xd118dc00, *startp=0xd6fdc000, size=16384, flags=0x1727)
1207516842.742601 uvm_map#3447358: uobj/offset 0xd07f35e0/-1
1207516842.742609 uvm_map_findspace#3470657: called!
1207516842.742615 uvm_map_findspace#3470657: (map=0xd118dc00, hint=0xd6fdc000, len=16384, flags=0x1727)
1207516842.742623 uvm_map#3447358: <- uvm_map_findspace failed!
1207516842.742629 uvm_km_alloc1#1091227: <- done (no VM)
1207516860.232615 uvm_fault#14742555: called!
1207516860.232619 uvm_fault#14742555: (map=0xd6a98524, vaddr=0xd308000, ft=0, at=1)
1207516860.232625 uvm_map_lookup_entry#21813712: called!
1207516860.232628 uvm_map_lookup_entry#21813712: (map=0xd6a98524,addr=0xd308000,ent=0xda540f3c)
1207516860.232632 uvm_map_lookup_entry#21813712: <- got it via hint (0xd6a3ab00)
1207516860.232637 uvm_fault#14742555: narrow=1, back=3, forw=4, startva=0xd305000
1207516860.232642 uvm_fault#14742555: entry=0xd6a3ab00, amap=0x0, obj=0xd6a60ccc
1207516860.232650 uvm_fault#14742555: shadowed=0, will_get=1
1207516860.232656 uvn_get#603322: called!
1207516860.232660 uvn_get#603322: flags=64
1207516860.232669 uvm_fault#14742555: MAPPING: n obj: pm=0xd6a9724c, va=0xd305000, pg=0xd0b45300
1207516860.232680 uvm_fault#14742555: MAPPING: n obj: pm=0xd6a9724c, va=0xd306000, pg=0xd0df3700
1207516860.232688 uvm_fault#14742555: MAPPING: n obj: pm=0xd6a9724c, va=0xd307000, pg=0xd0baba00
1207516860.232696 uvm_fault#14742555: got uobjpage (0xd0ec1100) with locked get
1207516860.232702 uvm_fault#14742555: MAPPING: n obj: pm=0xd6a9724c, va=0xd30c000, pg=0xd0b5cb80
1207516860.232708 uvm_fault#14742555: case 2 fault: promote=0, zfill=0
1207516860.232712 uvm_fault#14742555: MAPPING: case2: pm=0xd6a9724c, va=0xd308000, pg=0xd0ec1100, promote=0
1207516860.232719 uvm_fault#14742555: <- done (SUCCESS!)
1207516860.232750 uvm_map_lookup_entry#21813713: called!
1207516860.232755 uvm_map_lookup_entry#21813713: (map=0xd07cd740,addr=0xd17ec440,ent=0xda540e40)
1207516861.572636 uvm_fault#14742556: called!
1207516861.572640 uvm_fault#14742556: (map=0xd6a98b04, vaddr=0x84784000, ft=0, at=3)
1207516861.572644 uvm_map_lookup_entry#21813714: called!
1207516861.572648 uvm_map_lookup_entry#21813714: (map=0xd6a98b04,addr=0x84784000,ent=0xda550dc8)
1207516861.572654 uvm_map_lookup_entry#21813714: <- got it via hint (0xd699e4dc)
1207516861.572659 uvm_fault#14742556: narrow=1, back=2, forw=1, startva=0x84782000
1207516861.572664 uvm_fault#14742556: entry=0xd699e4dc, amap=0xda67a0b0, obj=0x0
1207516861.572669 amap_lookups#14350962: called!
1207516861.572674 amap_lookups#14350962: slot=0, npages=4, nslot=4
1207516861.572680 amap_lookups#14350962: <- done
1207516861.572686 uvm_fault#14742556: shadowed=1, will_get=0
1207516861.572691 uvm_fault#14742556: case 1 fault: anon=0xd6895150
1207516861.572694 uvmfault_anonget#1169762: called!
1207516861.572710 uvmfault_anonget#1169762: noram -- UVM_WAIT
1207516890.243627 uvm_map_lookup_entry#21813715: called!
1207516890.243631 uvm_map_lookup_entry#21813715: (map=0xd07cd740,addr=0xd187c640,ent=0xda540e40)
1207516913.235111 uvm_fault#14742557: called!
1207516913.235117 uvm_fault#14742557: (map=0xd6a98468, vaddr=0x84b13000, ft=0, at=3)
1207516913.235123 uvm_map_lookup_entry#21813716: called!
1207516913.235128 uvm_map_lookup_entry#21813716: (map=0xd6a98468,addr=0x84b13000,ent=0xda535de8)
1207516913.235136 uvm_fault#14742557: narrow=1, back=2, forw=1, startva=0x84b11000
1207516913.235142 uvm_fault#14742557: entry=0xd6a33a54, amap=0xd6a398f8, obj=0x0
1207516913.235146 amap_lookups#14350963: called!
1207516913.235149 amap_lookups#14350963: slot=0, npages=4, nslot=4
1207516913.235154 amap_lookups#14350963: <- done
1207516913.235160 uvm_fault#14742557: shadowed=1, will_get=0
1207516913.235163 uvm_fault#14742557: case 1 fault: anon=0xd6a27240
1207516913.235167 uvmfault_anonget#1169763: called!
1207516913.235183 uvmfault_anonget#1169763: noram -- UVM_WAIT
1207516920.254632 uvm_map_lookup_entry#21813717: called!
1207516920.254637 uvm_map_lookup_entry#21813717: (map=0xd07cd740,addr=0xd187c780,ent=0xda540e40)
1207516920.254642 uvm_map_lookup_entry#21813717: <- got it via hint (0xd0801e90)
1207516950.265642 uvm_map_lookup_entry#21813718: called!
1207516950.265647 uvm_map_lookup_entry#21813718: (map=0xd07cd740,addr=0xd16b5700,ent=0xda540e40)
1207516980.276656 uvm_map_lookup_entry#21813719: called!
1207516980.276660 uvm_map_lookup_entry#21813719: (map=0xd07cd740,addr=0xd17ec4c0,ent=0xda540e40)
1207517010.287667 uvm_map_lookup_entry#21813720: called!
1207517010.287670 uvm_map_lookup_entry#21813720: (map=0xd07cd740,addr=0xd16aa9c0,ent=0xda540e40)
1207517040.298672 uvm_map_lookup_entry#21813721: called!
1207517040.298678 uvm_map_lookup_entry#21813721: (map=0xd07cd740,addr=0xd175ad80,ent=0xda540e40)
1207517070.309682 uvm_map_lookup_entry#21813722: called!
1207517070.309686 uvm_map_lookup_entry#21813722: (map=0xd07cd740,addr=0xd134b4c0,ent=0xda540e40)
1207517100.320695 uvm_map_lookup_entry#21813723: called!
1207517100.320699 uvm_map_lookup_entry#21813723: (map=0xd07cd740,addr=0xd133b280,ent=0xda540e40)
1207517100.320704 uvm_map_lookup_entry#21813723: <- got it via hint (0xd07fe108)
1207517130.331710 uvm_map_lookup_entry#21813724: called!
1207517130.331716 uvm_map_lookup_entry#21813724: (map=0xd07cd740,addr=0xd1340880,ent=0xda540e40)
1207517130.331720 uvm_map_lookup_entry#21813724: <- got it via hint (0xd07fe108)
1207517160.342717 uvm_map_lookup_entry#21813725: called!
1207517160.342722 uvm_map_lookup_entry#21813725: (map=0xd07cd740,addr=0xd175ae00,ent=0xda540e40)
1207517190.353729 uvm_map_lookup_entry#21813726: called!
1207517190.353734 uvm_map_lookup_entry#21813726: (map=0xd07cd740,addr=0xd175adc0,ent=0xda540e40)
1207517190.353739 uvm_map_lookup_entry#21813726: <- got it via hint (0xd07ffde8)
1207517220.364736 uvm_map_lookup_entry#21813727: called!
1207517220.364740 uvm_map_lookup_entry#21813727: (map=0xd07cd740,addr=0xd1758d00,ent=0xda540e40)
1207517220.364744 uvm_map_lookup_entry#21813727: <- got it via hint (0xd07ffde8)
1207517250.375748 uvm_map_lookup_entry#21813728: called!
1207517250.375752 uvm_map_lookup_entry#21813728: (map=0xd07cd740,addr=0xd16ae2c0,ent=0xda540e40)
1207517280.386758 uvm_map_lookup_entry#21813729: called!
1207517280.386761 uvm_map_lookup_entry#21813729: (map=0xd07cd740,addr=0xd16ae180,ent=0xda540e40)
1207517280.386765 uvm_map_lookup_entry#21813729: <- got it via hint (0xd0804510)
0
ddb> call uvmcnt_dump()
# map lookup hint hits = 16360224
# map lookup calls = 21813730
# uvm_map() missed forward = 2518
# uvm_map() back merges = 588872
# uvm_map() successful calls = 2861697
0x27
ddb> boot crash


OpenBSD 4.3-current (U80) #1: Sun Apr 6 12:00:19 EDT 2008
rd@a8v.thrush.com:/usr/src/sys/arch/i386/compile/U80
cpu0: Geode(TM) Integrated Processor by AMD PCS ("AuthenticAMD" 586-class) 500 MHz
cpu0: FPU,DE,PSE,TSC,MSR,CX8,SEP,PGE,CMOV,CFLUSH,MMX
real mem = 536440832 (511MB)
avail mem = 510484480 (486MB)
mainbus0 at root
bios0 at mainbus0: AT/286+ BIOS, date 20/71/05, BIOS32 rev. 0 @ 0xfac40
pcibios0 at bios0: rev 2.0 @ 0xf0000/0x10000
pcibios0: pcibios_get_intr_routing - function not supported
pcibios0: PCI IRQ Routing information unavailable.
pcibios0: PCI bus #0 is the last bus
bios0: ROM list: 0xc8000/0xa800
cpu0 at mainbus0
pci0 at mainbus0 bus 0: configuration mode 1 (bios)
pchb0 at pci0 dev 1 function 0 "AMD Geode LX" rev 0x30
glxsb0 at pci0 dev 1 function 2 "AMD Geode LX Crypto" rev 0x00: RNG AES
vr0 at pci0 dev 6 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 11, address 00:00:24:c9:29:14
ukphy0 at vr0 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI 0x004063, model 0x0034
vr1 at pci0 dev 7 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 5, address 00:00:24:c9:29:15
ukphy1 at vr1 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI 0x004063, model 0x0034
vr2 at pci0 dev 8 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 9, address 00:00:24:c9:29:16
ukphy2 at vr2 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI 0x004063, model 0x0034
vr3 at pci0 dev 9 function 0 "VIA VT6105M RhineIII" rev 0x96: irq 12, address 00:00:24:c9:29:17
ukphy3 at vr3 phy 1: Generic IEEE 802.3u media interface, rev. 3: OUI 0x004063, model 0x0034
glxpcib0 at pci0 dev 20 function 0 "AMD CS5536 ISA" rev 0x03: rev 0, 32-bit 3579545Hz timer, watchdog, gpio
gpio0 at glxpcib0: 32 pins
pciide0 at pci0 dev 20 function 2 "AMD CS5536 IDE" rev 0x01: DMA, channel 0 wired to compatibility, channel 1 wired to compatibility
wd0 at pciide0 channel 0 drive 0: <ST3808110AS>
wd0: 16-sector PIO, LBA48, 76319MB, 156301488 sectors
wd1 at pciide0 channel 0 drive 1: <TRANSCEND>
wd1: 1-sector PIO, LBA, 1911MB, 3915072 sectors
wd0(pciide0:0:0): using PIO mode 4, Ultra-DMA mode 2
wd1(pciide0:0:1): using PIO mode 4, Ultra-DMA mode 2
pciide0: channel 1 ignored (disabled)
ohci0 at pci0 dev 21 function 0 "AMD CS5536 USB" rev 0x02: irq 15, version 1.0, legacy support
ehci0 at pci0 dev 21 function 1 "AMD CS5536 USB" rev 0x02: irq 15
usb0 at ehci0: USB revision 2.0
uhub0 at usb0 "AMD EHCI root hub" rev 2.00/1.00 addr 1
isa0 at glxpcib0
isadma0 at isa0
pckbc0 at isa0 port 0x60/5
pckbd0 at pckbc0 (kbd slot)
pckbc0: using irq 1 for kbd slot
wskbd0 at pckbd0: console keyboard
pcppi0 at isa0 port 0x61
midi0 at pcppi0: <PC speaker>
spkr0 at pcppi0
nsclpcsio0 at isa0 port 0x2e/2: NSC PC87366 rev 9: GPIO VLM TMS
gpio1 at nsclpcsio0: 29 pins
npx0 at isa0 port 0xf0/16: reported by CPUID; using exception 16
pccom0 at isa0 port 0x3f8/8 irq 4: ns16550a, 16 byte fifo
pccom0: console
pccom1 at isa0 port 0x2f8/8 irq 3: ns16550a, 16 byte fifo
usb1 at ohci0: USB revision 1.0
uhub1 at usb1 "AMD OHCI root hub" rev 1.00/1.00 addr 1
biomask e5c5 netmask ffe5 ttymask ffe7
mtrr: K6-family MTRR support (2 registers)
softraid0 at root
root on wd0a swap on wd0b dump on wd0b
WARNING: / was not properly unmounted