Subject: panic "malloc: out of space in kmem_map" with UVM
To: None <current-users@NetBSD.ORG>
From: Kazushi (Jam) Marukawa <jam@pobox.com>
List: current-users
Date: 05/16/1998 01:16:49
   On May 15, 17:43, Kazushi (Jam) Marukawa wrote:
   > Subject: Re: UVM deadlock?
   > Currently, my system which has 128 MB memories works fine
   > after eliminating the KMEMSTATS definition.  I rebuilt my
   > system about 2 hours ago.  Before the rebuilding, the system
   > was halted every time when I tried to link a mozilla
   > statically.  But now it works fine.

I should say a kernel without KMEMSTATS worked better than a
kernel with KMEMSTATS.  When I'm using my system normally,
the statically linking of a mozilla made "malloc: out of
space in kmem_map" panic.


db> trace
_Debugger(c,c000,f7eaae58,f014c0a6,f014bdf4) at _Debugger+0x4
_panic(f014bdf4,b028,f0af5e40,0,c000) at _panic+0x55
_malloc(b028,52,0,b028,52) at _malloc+0x1d6
_amap_extend(f0b00d00,1000) at _amap_extend+0x4e7
_uvm_map(f09fb000,f7eaaf3c,1000,0,0,1b0717) at _uvm_map+0x952
_sys_obreak(f0a23c00,f7eaaf88,f7eaaf80,0,0) at _sys_obreak+0x80
_syscall() at _syscall+0x274
--- syscall (number 17) ---
0x4007d375:
db> call uvmhist_dump(maphist)
895296523.073394 uvm_fault#1380013:   MAPPING: case2: pm=0xf0b00bc0, va=0x2c19000, pg=0xf0574f50, promote=1
895296523.073403 uvm_fault#1380013: <- done (SUCCESS!)
895296523.074212 uvm_map_lookup_entry#5939880: called!
895296523.074217 uvm_map_lookup_entry#5939880: (map=0xf0315910,addr=0xf0abde00,ent=0xf7eaad44)
895296523.074246 uvm_map_lookup_entry#5939880: <- search got it (0xf0326224)
895296523.078109 uvm_pagermapout#20964: called!
895296523.078116 uvm_pagermapout#20964:  (kva=0xf0bdd000, npages=16)
895296523.078130 uvm_unmap_remove#193431: called!
895296523.078139 uvm_unmap_remove#193431: (map=0xf05ddf00, start=0xf0bdd000, end=0xf0bed000)
895296523.078147 uvm_map_lookup_entry#5939881: called!
895296523.078152 uvm_map_lookup_entry#5939881: (map=0xf05ddf00,addr=0xf0bdd000,ent=0xf7de2e00)
895296523.078158 uvm_map_lookup_entry#5939881: <- got it via hint (0xf03269a4)
895296523.078185 uvm_unmap_remove#193431:   removed map entry 0xf03269a4
895296523.078193 uvm_unmap_remove#193431: <- done!
895296523.078204 uvm_unmap_detach#193416: called!
895296523.078211 uvm_unmap_detach#193416:   detach 0xf03269a4: amap=0x0, obj=0x0, map?=0
895296523.078220 uvm_mapent_free#501200: called!
895296523.078229 uvm_mapent_free#501200: <- freeing map entry=0xf03269a4 [flags=1]
895296523.078237 uvm_unmap_detach#193416: <- done
895296523.078244 uvm_pagermapout#20964: <- done
895296523.091859 uvm_pagermapout#20965: called!
895296523.091868 uvm_pagermapout#20965:  (kva=0xf0bed000, npages=16)
895296523.091883 uvm_unmap_remove#193432: called!
895296523.091889 uvm_unmap_remove#193432: (map=0xf05ddf00, start=0xf0bed000, end=0xf0bfd000)
895296523.091898 uvm_map_lookup_entry#5939882: called!
895296523.091904 uvm_map_lookup_entry#5939882: (map=0xf05ddf00,addr=0xf0bed000,ent=0xf7de2e00)
895296523.091912 uvm_map_lookup_entry#5939882: <- got it via hint (0xf032584c)
895296523.091937 uvm_unmap_remove#193432:   removed map entry 0xf032584c
895296523.091945 uvm_unmap_remove#193432: <- done!
895296523.091954 uvm_unmap_detach#193417: called!
895296523.091961 uvm_unmap_detach#193417:   detach 0xf032584c: amap=0x0, obj=0x0, map?=0
895296523.091967 uvm_mapent_free#501201: called!
895296523.091974 uvm_mapent_free#501201: <- freeing map entry=0xf032584c [flags=1]
895296523.091982 uvm_unmap_detach#193417: <- done
895296523.091988 uvm_pagermapout#20965: <- done
895296523.092141 uvm_pageout#0:   <<SLEEPING>>
895296523.109343 uvm_map_lookup_entry#5939883: called!
895296523.109349 uvm_map_lookup_entry#5939883: (map=0xf0315910,addr=0xf0b00cc0,ent=0xf7eaad44)
895296523.109366 uvm_map_lookup_entry#5939883: <- search got it (0xf0325ae0)
895296523.110888 uvm_map_lookup_entry#5939884: called!
895296523.110893 uvm_map_lookup_entry#5939884: (map=0xf0315910,addr=0xf0a17700,ent=0xf7e32df8)
895296523.110906 uvm_map_lookup_entry#5939884: <- search got it (0xf0326080)
895296523.112703 uvm_map_lookup_entry#5939885: called!
895296523.112710 uvm_map_lookup_entry#5939885: (map=0xf0315910,addr=0xf0ab7080,ent=0xf7e3be38)
895296523.112726 uvm_map_lookup_entry#5939885: <- search got it (0xf03262d8)
895296523.117131 uvm_fault#1380014: called!
895296523.117138 uvm_fault#1380014: (map=0xf09fb000, vaddr=0x769000, ft=0, at=1)
895296523.117147 uvm_map_lookup_entry#5939886: called!
895296523.117152 uvm_map_lookup_entry#5939886: (map=0xf09fb000,addr=0x769000,ent=0xf7eaaf50)
895296523.117159 uvm_map_lookup_entry#5939886: <- got it via hint (0xf0b00d00)
895296523.117172 uvm_fault#1380014:   narrow=0, back=3, forw=4, orig_startva=0x766000
895296523.117181 uvm_fault#1380014:   entry=0xf0b00d00, amap=0xf0af5e40, obj=0x0
895296523.117190 amap_lookups#1055219: called!
895296523.117197 amap_lookups#1055219:   slot=1877, npages=8, nslot=11273
895296523.117206 amap_lookups#1055219: <- done
895296523.117224 uvm_fault#1380014:   MAPPING: n anon: pm=0xf0b00bc0, va=0x766000, pg=0xf04b5454
895296523.117254 uvm_fault#1380014:   MAPPING: n anon: pm=0xf0b00bc0, va=0x767000, pg=0xf04819d0
895296523.117264 uvm_fault#1380014:   MAPPING: n anon: pm=0xf0b00bc0, va=0x768000, pg=0xf0471464
895296523.117275 uvm_fault#1380014:   MAPPING: n anon: pm=0xf0b00bc0, va=0x76a000, pg=0xf05364b0
895296523.117286 uvm_fault#1380014:   MAPPING: n anon: pm=0xf0b00bc0, va=0x76b000, pg=0xf049130c
895296523.117296 uvm_fault#1380014:   MAPPING: n anon: pm=0xf0b00bc0, va=0x76c000, pg=0xf0589e78
895296523.117305 uvm_fault#1380014:   shadowed=1, will_get=0
895296523.117313 uvm_fault#1380014:   case 1 fault: anon=0xf08dc320
895296523.117322 uvmfault_anonget#428377: called!
895296523.117334 uvmfault_anonget#428377: <- OK
895296523.117342 uvm_fault#1380014:   MAPPING: anon: pm=0xf0b00bc0, va=0x769000, pg=0xf04502a4
895296523.125675 uvm_map#519104: called!
895296523.125684 uvm_map#519104: (map=0xf09fb000, *startp=0x2c1a000, size=4096, flags=0x1b0717)
895296523.125691 uvm_map#519104:   uobj/offset 0x0/-1
895296523.125702 uvm_map_findspace#519104: called!
895296523.125708 uvm_map_findspace#519104: (map=0xf09fb000, hint=0x2c1a000, len=4096, fixed=65536)
895296523.125717 uvm_map_lookup_entry#5939887: called!
895296523.125722 uvm_map_lookup_entry#5939887: (map=0xf09fb000,addr=0x2c1a000,ent=0xf7eaaea4)
895296523.125730 uvm_map_lookup_entry#5939887: <- failed!
895296523.125736 uvm_map_findspace#519104: <- got it!  (result=0x2c1a000)
895296523.125747 uvm_map#519104:   starting back merge
895296523.125756 amap_extend#252335: called!
895296523.125762 amap_extend#252335:   (entry=0xf0b00d00, addsize=0x1000)
895296523.125778 uvm_km_kmemalloc#32980: called!
895296523.125785 uvm_km_kmemalloc#32980:   (map=0xf0315910, obj=0xf0318310, size=0xc000, flags=0)
895296523.125794 uvm_map#519105: called!
895296523.125798 uvm_map#519105: (map=0xf0315910, *startp=0xf05dd000, size=49152, flags=0x1727)
895296523.125803 uvm_map#519105:   uobj/offset 0xf0318310/-1
895296523.125809 uvm_map_findspace#519105: called!
895296523.125813 uvm_map_findspace#519105: (map=0xf0315910, hint=0xf05dd000, len=49152, fixed=0)
895296523.125843 uvm_map_findspace#519105: <- got it!  (result=0xf0b7a000)
895296523.125849 uvm_map#519105:   starting back merge
895296523.125855 uvm_map#519105: <- done (via backmerge)!
895296523.125864 uvm_km_kmemalloc#32980:   kva=0xf0b7a000, offset=0xb7a000
895296523.125908 uvm_km_kmemalloc#32980: <- done (kva=0xf0b7a000)
895296523.125916 uvm_km_kmemalloc#32981: called!
895296523.125921 uvm_km_kmemalloc#32981:   (map=0xf0315910, obj=0xf0318310, size=0xc000, flags=0)
895296523.125926 uvm_map#519106: called!
895296523.125931 uvm_map#519106: (map=0xf0315910, *startp=0xf05dd000, size=49152, flags=0x1727)
895296523.125935 uvm_map#519106:   uobj/offset 0xf0318310/-1
895296523.125942 uvm_map_findspace#519106: called!
895296523.125946 uvm_map_findspace#519106: (map=0xf0315910, hint=0xf05dd000, len=49152, fixed=0)
895296523.125961 uvm_map_findspace#519106: <- failed (off end)
895296523.125968 uvm_map#519106: <- uvm_map_findspace failed!
895296523.125975 uvm_km_kmemalloc#32981: <- done (no VM)
0xa0000003
db> call uvmhist_dump(pdhist)
895296522.943097 uvm_swap_aiodone#1949: called!
895296522.943106 uvm_swap_aiodone#1949: done with aio 0xf06c9ec4
895296522.943296 uvm_pageout#0:   free/ftarg=78/85, inact/itarg=9339/9336
895296522.943305 uvmpd_scan#6738: called!
895296522.943312 uvmpd_scan#6738:   free 78 < target 85: swapout
895296522.943375 uvmpd_scan#6738:   starting 'free' loop
895296522.943383 uvmpd_scan_inactive#10562: called!
895296522.943406 uvmpd_scan_inactive#10562:   met free target: exit loop
895296522.943412 uvmpd_scan#6738:   second loop: page_shortage=4
895296522.971216 uvm_pageout#0:   <<WOKE UP>>
895296522.971230 uvm_pageout#0:   free/ftarg=62/85, inact/itarg=9336/9341
895296522.971243 uvmpd_scan#6739: called!
895296522.971255 uvmpd_scan#6739:   free 62 < target 85: swapout
895296522.971321 uvmpd_scan#6739:   starting 'free' loop
895296522.971333 uvmpd_scan_inactive#10563: called!
895296522.971383 uvmpd_scan_inactive#10564: called!
895296522.971423 uvm_swap_alloc#1950: called!
895296522.971478 uvm_swap_alloc#1950: success!  returning 16 slots starting at 9574
895296522.971535 uvm_swap_io#5392: called!
895296522.971543 uvm_swap_io#5392: <- called, startslot=9574, npages=16, flags=4
895296522.971689 uvm_swap_io#5392: doing async!
895296522.971696 uvm_swap_io#5392: about to start io: data = 0x0xf0bdd000 blkno = 0x12b30, bcount = 65536
895296522.971708 swstrategy#6037: called!
895296522.971717 swstrategy#6037:   write: mapoff=1 bn=12b28 bcount=65536

895296522.984634 uvm_swap_bufdone#1950: called!
895296522.984643 uvm_swap_bufdone#1950: cleaning buf 0xf0fe89f8
895296522.985037 uvmpd_scan#6739:   second loop: page_shortage=21
895296522.985118 uvm_swap_aiodone#1950: called!
895296522.985126 uvm_swap_aiodone#1950: done with aio 0xf06c9ec4
895296522.985319 uvm_pageout#0:   free/ftarg=78/85, inact/itarg=9341/9336
895296522.985327 uvmpd_scan#6740: called!
895296522.985334 uvmpd_scan#6740:   free 78 < target 85: swapout
895296522.985394 uvmpd_scan#6740:   starting 'free' loop
895296522.985402 uvmpd_scan_inactive#10565: called!
895296522.985428 uvmpd_scan_inactive#10565:   met free target: exit loop
895296522.985434 uvmpd_scan#6740:   second loop: page_shortage=2
895296523.029413 uvm_pageout#0:   <<WOKE UP>>
895296523.029423 uvm_pageout#0:   free/ftarg=84/85, inact/itarg=9335/9334
895296523.029433 uvmpd_scan#6741: called!
895296523.029443 uvmpd_scan#6741:   free 84 < target 85: swapout
895296523.029512 uvmpd_scan#6741:   starting 'free' loop
895296523.029523 uvmpd_scan_inactive#10566: called!
895296523.029542 uvmpd_scan_inactive#10566:   met free target: exit loop
895296523.029550 uvmpd_scan#6741:   second loop: page_shortage=0
895296523.049040 uvm_pageout#0:   <<WOKE UP>>
895296523.049047 uvm_pageout#0:   free/ftarg=80/85, inact/itarg=9334/9334
895296523.049055 uvmpd_scan#6742: called!
895296523.049062 uvmpd_scan#6742:   free 80 < target 85: swapout
895296523.049116 uvmpd_scan#6742:   starting 'free' loop
895296523.049123 uvmpd_scan_inactive#10567: called!
895296523.049149 uvmpd_scan_inactive#10567:   met free target: exit loop
895296523.049157 uvmpd_scan#6742:   second loop: page_shortage=5
895296523.058006 uvm_pageout#0:   <<WOKE UP>>
895296523.058015 uvm_pageout#0:   free/ftarg=62/85, inact/itarg=9334/9340
895296523.058022 uvmpd_scan#6743: called!
895296523.058030 uvmpd_scan#6743:   free 62 < target 85: swapout
895296523.058094 uvmpd_scan#6743:   starting 'free' loop
895296523.058101 uvmpd_scan_inactive#10568: called!
895296523.058123 uvmpd_scan_inactive#10569: called!
895296523.058150 uvm_swap_alloc#1951: called!
895296523.058216 uvm_swap_alloc#1951: success!  returning 16 slots starting at 27373
895296523.058282 uvm_swap_io#5393: called!
895296523.058290 uvm_swap_io#5393: <- called, startslot=27373, npages=16, flags=4
895296523.058428 uvm_swap_io#5393: doing async!
895296523.058435 uvm_swap_io#5393: about to start io: data = 0x0xf0bdd000 blkno = 0x35768, bcount = 65536
895296523.058449 swstrategy#6038: called!
895296523.058463 swstrategy#6038:   write: mapoff=1 bn=35760 bcount=65536

895296523.058559 uvm_swap_alloc#1952: called!
895296523.058572 uvm_swap_alloc#1952: success!  returning 16 slots starting at 27389
895296523.058633 uvm_swap_io#5394: called!
895296523.058641 uvm_swap_io#5394: <- called, startslot=27389, npages=16, flags=4
895296523.058733 uvm_swap_io#5394: doing async!
895296523.058737 uvm_swap_io#5394: about to start io: data = 0x0xf0bed000 blkno = 0x357e8, bcount = 65536
895296523.058745 swstrategy#6039: called!
895296523.058750 swstrategy#6039:   write: mapoff=1 bn=357e0 bcount=65536

895296523.072834 uvmpd_scan#6743:   second loop: page_shortage=11
895296523.078022 uvm_swap_bufdone#1951: called!
895296523.078031 uvm_swap_bufdone#1951: cleaning buf 0xf0fe89f8
895296523.078065 uvm_pageout#0:   <<WOKE UP>>
895296523.078078 uvm_swap_aiodone#1951: called!
895296523.078085 uvm_swap_aiodone#1951: done with aio 0xf06c9ec4
895296523.078292 uvm_pageout#0:   free/ftarg=65/85, inact/itarg=9340/9339
895296523.078301 uvmpd_scan#6744: called!
895296523.078309 uvmpd_scan#6744:   free 65 < target 85: swapout
895296523.078393 uvmpd_scan#6744:   starting 'free' loop
895296523.078406 uvmpd_scan_inactive#10570: called!
895296523.084632 uvm_swap_bufdone#1952: called!
895296523.084640 uvm_swap_bufdone#1952: cleaning buf 0xf0fe89f8
895296523.091755 uvmpd_scan_inactive#10571: called!
895296523.091765 uvmpd_scan#6744:   second loop: page_shortage=15
895296523.091830 uvm_swap_aiodone#1952: called!
895296523.091837 uvm_swap_aiodone#1952: done with aio 0xf06c9f54
895296523.092025 uvm_pageout#0:   free/ftarg=81/85, inact/itarg=9339/9334
895296523.092034 uvmpd_scan#6745: called!
895296523.092040 uvmpd_scan#6745:   free 81 < target 85: swapout
895296523.092099 uvmpd_scan#6745:   starting 'free' loop
895296523.092106 uvmpd_scan_inactive#10572: called!
895296523.092111 uvmpd_scan_inactive#10573: called!
895296523.092128 uvmpd_scan_inactive#10573:   met free target: exit loop
895296523.092135 uvmpd_scan#6745:   second loop: page_shortage=-1
0xa0000003

-- Kazushi
As of next week, passwords will be entered in Morse code.