allegro-cl archives 1996-8-22 | home index prev H thread prev K thread-next J next L |
From: pa (Patrick A. O'Donnell) Subject: Global GC performance Date: 1996-8-22 12:43 This message was directed to <franz.com, at bugs> but if anyone on the Allegro-CL list has any suggestions to offer, they would be most welcome. I originally typed the address for allegro-cl incorrectly, so this is being sent separately from the original message. The text below is identical. We have some large but interactive applications which we are in the process of porting from Lucid Lisp to Allegro CL (4.3). Sadly, we have run into a show-stopper for delivering our applications: global GCs which take 8 or 11 minutes. These applications are in decision support roles presenting massive amounts of data intelligibly to our users, and our users need to act on that information quickly -- within minutes. Waiting for 10 or so minutes for a GC to complete is not acceptable. This is exactly the sort of behavior that has dirtied the name 'Lisp' in the minds of the public; I had thought we had put this behind us years ago. I need ideas. I've included below some output from (room) and verbose GC output from one of our applications. (In this sample, I had built the application to start with one very large "oldspace", believing that that might help the performance. The manual seemed to imply that it would. I think it made things worse.) I can supply more details, if needed. I hope GC performance is high on your priority list for enhancement. GC was not nearly this slow under Lucid, so we know that the performance does not have to be this bad despite the size and memory use of our application. The situation is very serious. We're forced to accept that we cannot deliver this application to our clients in its current state. We have hit many difficulties before, but this is the first time we fear that Allegro CL may not be the means by which we fulfill our contractual obligations. - Pat ------------------------------------------------------------------------------- Patrick A. O'Donnell Ascent Technology, Inc. Development Scientist 64 Sidney St, Cambridge, MA 02139-4136 <ascent.com at pao> 617-225-0850 x305 ===================================================================== What follows is a script of GC-related output from the run of one of our applications as mentioned above. The sample run was from a snapshot data set, which is why the date and time of the log messages are from December. Some irrelevant log messages have been elided. 22-Dec 17:01> Loading new data. scavenging...done eff: 89%, copy new: 6015248 + old: 1205736 = 7220984 Page faults: non-gc = 605 major + 0 minor, gc = 141 major + 0 minor Set max update to 4668134 after LOAD 22-Dec 17:01> Beginning load of maintenance data ... scavenging...done eff: 94%, copy new: 4783920 + old: 2242608 = 7026528 Page faults: non-gc = 237 major + 0 minor, gc = 10 major + 0 minor scavenging...done eff: 97%, copy new: 5092368 + old: 1421912 = 6514280 Page faults: non-gc = 33 major + 0 minor, gc = 14 major + 0 minor scavenging...done eff: 96%, copy new: 4837072 + old: 1814400 = 6651472 Page faults: non-gc = 16 major + 0 minor, gc = 95 major + 0 minor [Started GC] scavenging...done Mark Pass...done(7,920+3,710), marked 1135261 objects, max depth = 46, cut 0 xfers. Weak-vector Pass...done(0+10). Cons-cell swap...done(50+240), 1778 cons cells moved Symbol-cell swap...done(20+20), 41 symbol cells moved Oldarea break chain...done(410+40), 174 holes totalling 245224 bytes Page-compaction data...done(0+0). Address adjustment...done(8,620+4,380). Compacting other objects...done(980+1,010). Page compaction...done(0+290), 0 pages moved New rootset...done(2,780+180), 58060 rootset entries Building new pagemap...done(480+40). Merging empty oldspaces...done, 0 oldspaces merged. global gc recovered 260512 bytes of old space. scavenging...done eff: 0%, copy new: 4445632 + old: 0 = 4445632 Page faults: non-gc = 177 major + 0 minor, gc = 9886 major + 0 minor [Finished GC] GC took 2.6 minutes scavenging...done eff: 99%, copy new: 6379952 + old: 0 = 6379952 Page faults: non-gc = 218 major + 0 minor, gc = 380 major + 0 minor scavenging...done eff: 94%, copy new: 6556720 + old: 1041192 = 7597912 Page faults: non-gc = 38 major + 0 minor, gc = 67 major + 0 minor 22-Dec 17:01> Reading maintenance assignments scavenging...done eff: 95%, copy new: 5995056 + old: 1416096 = 7411152 Page faults: non-gc = 708 major + 0 minor, gc = 38 major + 0 minor scavenging...done eff: 82%, copy new: 4868336 + old: 1247176 = 6115512 Page faults: non-gc = 523 major + 0 minor, gc = 16 major + 0 minor scavenging...done eff: 83%, copy new: 4878912 + old: 1110720 = 5989632 Page faults: non-gc = 13 major + 0 minor scavenging...done eff: 84%, copy new: 3193480 + old: 1733320 = 4926800 Page faults: non-gc = 179 major + 0 minor, gc = 584 major + 0 minor [Started GC] scavenging...done Mark Pass...done(9,700+3,460), marked 1237428 objects, max depth = 47, cut 0 xfers. Weak-vector Pass...done(0+0). Cons-cell swap...done(30+40), 725 cons cells moved Symbol-cell swap...done(20+0), 0 symbol cells moved Oldarea break chain...done(580+230), 12 holes totalling 8400 bytes Page-compaction data...done(10+0). Address adjustment...done(7,840+810). Compacting other objects...done(560+60). Page compaction...done(10+90), 0 pages moved New rootset...done(3,680+1,030), 1930 rootset entries Building new pagemap...done(630+450). Merging empty oldspaces...done, 0 oldspaces merged. global gc recovered 14240 bytes of old space. scavenging...done eff: 0%, copy new: 2338664 + old: 0 = 2338664 Page faults: non-gc = 52 major + 0 minor, gc = 11034 major + 0 minor [Finished GC] GC took 3.1833334 minutes ;;; ;;; ---- The following was from the application running overnight. ;;; Periodically, it was processing "updates" from the ;;; database, but actual update activity was, in fact, minimal or ;;; non-existent. ;;; scavenging...done eff: 95%, copy new: 2403360 + old: 0 = 2403360 Page faults: non-gc = 288 major + 0 minor, gc = 248 major + 0 minor scavenging...done eff: 94%, copy new: 1299816 + old: 1154896 = 2454712 Page faults: non-gc = 66 major + 0 minor, gc = 22 major + 0 minor scavenging...done eff: 95%, copy new: 1506592 + old: 52384 = 1558976 Page faults: non-gc = 1162 major + 0 minor, gc = 11 major + 0 minor scavenging...done eff: 97%, copy new: 1529312 + old: 40496 = 1569808 Page faults: non-gc = 127 major + 0 minor, gc = 5 major + 0 minor scavenging...done eff: 98%, copy new: 1483496 + old: 46280 = 1529776 Page faults: gc = 4 major + 0 minor scavenging...done eff: 98%, copy new: 1373560 + old: 109384 = 1482944 Page faults: non-gc = 2 major + 0 minor, gc = 352 major + 0 minor scavenging...done eff: 98%, copy new: 66840 + old: 1306704 = 1373544 Page faults: non-gc = 1833 major + 0 minor, gc = 89 major + 0 minor scavenging...done eff: 99%, copy new: 2904 + old: 63952 = 66856 Page faults: non-gc = 1793 major + 0 minor, gc = 3 major + 0 minor scavenging...done eff: 99%, copy new: 3000 + old: 0 = 3000 scavenging...done eff: 99%, copy new: 8200 + old: 0 = 8200 Page faults: non-gc = 3 major + 0 minor, gc = 8 major + 0 minor scavenging...done eff: 99%, copy new: 2816 + old: 48 = 2864 Page faults: non-gc = 1587 major + 0 minor, gc = 13 major + 0 minor scavenging...done eff: 99%, copy new: 2992 + old: 0 = 2992 Page faults: non-gc = 1103 major + 0 minor scavenging...done eff: 99%, copy new: 2768 + old: 0 = 2768 scavenging...done eff: 99%, copy new: 2904 + old: 0 = 2904 Page faults: non-gc = 1 major + 0 minor, gc = 13 major + 0 minor scavenging...done eff: 99%, copy new: 2904 + old: 0 = 2904 Page faults: non-gc = 1580 major + 0 minor, gc = 2 major + 0 minor scavenging...done eff: 99%, copy new: 2920 + old: 0 = 2920 Page faults: non-gc = 1053 major + 0 minor, gc = 1 major + 0 minor scavenging...done eff: 99%, copy new: 2896 + old: 0 = 2896 scavenging...done eff: 99%, copy new: 2864 + old: 0 = 2864 Page faults: non-gc = 9 major + 0 minor, gc = 35 major + 0 minor scavenging...done eff: 99%, copy new: 2856 + old: 0 = 2856 Page faults: non-gc = 2817 major + 0 minor, gc = 2 major + 0 minor scavenging...done eff: 99%, copy new: 2936 + old: 0 = 2936 Page faults: non-gc = 2245 major + 0 minor, gc = 2 major + 0 minor scavenging...done eff: 99%, copy new: 2880 + old: 0 = 2880 scavenging...done eff: 99%, copy new: 2840 + old: 0 = 2840 Page faults: non-gc = 12 major + 0 minor, gc = 3 major + 0 minor scavenging...done eff: 99%, copy new: 2832 + old: 0 = 2832 Page faults: non-gc = 2105 major + 0 minor, gc = 3 major + 0 minor scavenging...done eff: 99%, copy new: 2808 + old: 0 = 2808 Page faults: non-gc = 1706 major + 0 minor scavenging...done eff: 99%, copy new: 2888 + old: 0 = 2888 scavenging...done eff: 99%, copy new: 2928 + old: 0 = 2928 Page faults: non-gc = 203 major + 0 minor, gc = 39 major + 0 minor scavenging...done eff: 99%, copy new: 2888 + old: 0 = 2888 Page faults: non-gc = 2647 major + 0 minor, gc = 3 major + 0 minor scavenging...done eff: 99%, copy new: 3000 + old: 0 = 3000 scavenging...done eff: 99%, copy new: 2880 + old: 0 = 2880 Page faults: gc = 1 major + 0 minor Error: Received signal number 2 (Keyboard interrupt) [condition type: INTERRUPT-SIGNAL] Restart actions (select using :continue): 0: continue computation 1: Restart the ARIS/AR application 2: Reload all known patch files [1c] <cl> (room t) area address(bytes) cons symbols other bytes 8 bytes each 24 bytes each (free:used) (free:used) (free:used) Top #x40c2000 New #x35ba000(11567104) ----- ----- ----- New #x2ab2000(11567104) 792:51177 253:1 7679288:3404976 Old #x98f50(44142768) 360:793441 187:63884 5981640:30209544 Root pages: 44 code type items bytes 96: (SIMPLE-ARRAY T) 119126 15351512 37.4% 1: CONS 842858 6742864 16.4% 101: (SIMPLE-ARRAY CHARACTER) 192373 6202352 15.1% 108: (SIMPLE-ARRAY CODE) 13102 6181608 15.1% 15: STRUCTURE 79578 2595456 6.3% 7: SYMBOL 63885 1533240 3.7% 8: FUNCTION 21636 1336536 3.3% 18: BIGNUM 48931 402392 1.0% 9: CLOSURE 14114 225824 0.6% 10: HASH-TABLE 3982 127424 0.3% 97: (SIMPLE-ARRAY BIT) 88 110520 0.3% 12: STANDARD-INSTANCE 5086 81376 0.2% 17: DOUBLE-FLOAT 3265 52240 0.1% 16: SINGLE-FLOAT 3047 24376 0.1% 99: (SIMPLE-ARRAY (UNSIGNED-BYTE 16)) 63 22288 0.1% 105: (SIMPLE-ARRAY (SIGNED-BYTE 16)) 5 6464 0.0% 98: (SIMPLE-ARRAY (UNSIGNED-BYTE 8)) 139 3840 0.0% 100: (SIMPLE-ARRAY (UNSIGNED-BYTE 32)) 63 2712 0.0% 65: (ARRAY BIT) 85 2040 0.0% 64: (ARRAY T) 30 720 0.0% 69: (ARRAY CHARACTER) 29 696 0.0% 19: RATIO 17 272 0.0% 20: COMPLEX 11 176 0.0% 11: READTABLE 8 128 0.0% 107: (SIMPLE-ARRAY (SIGNED-BYTE 32)) 2 104 0.0% 13: SYSVECTOR 2 32 0.0% total bytes = 41007192 malloc arena: max size free bytes used bytes total 8 888 1160 2048 24 1536 4608 6144 56 2800 784 3584 120 2280 1560 3840 504 4032 4032 8064 1016 4064 0 4064 2040 6120 14280 20400 4088 4088 0 4088 5112 20448 0 20448 9208 27624 9208 36832 total bytes: 73880 35632 109512 Reserved malloc space at #x89000: 61440 bytes reserved, 57344 bytes bucketed (4096 bytes unassigned) 45056 additional malloc bytes bucketed before reserved area [1c] <cl> :cont 0 scavenging...done eff: 99%, copy new: 98504 + old: 0 = 98504 Page faults: non-gc = 10214 major + 0 minor, gc = 73 major + 0 minor 23-Dec 7:54> RELOAD: ... 23-Dec 7:54> Clearing extraneous data. 23-Dec 7:54> Loading new data. scavenging...done eff: 98%, copy new: 2324016 + old: 0 = 2324016 Page faults: non-gc = 3581 major + 0 minor, gc = 6 major + 0 minor scavenging...done eff: 96%, copy new: 4989352 + old: 0 = 4989352 Page faults: non-gc = 53 major + 0 minor, gc = 1 major + 0 minor scavenging...done eff: 94%, copy new: 5927000 + old: 0 = 5927000 Page faults: non-gc = 64 major + 0 minor scavenging...done eff: 92%, copy new: 6666424 + old: 92296 = 6758720 Page faults: non-gc = 2 major + 0 minor, gc = 3 major + 0 minor scavenging...done eff: 89%, copy new: 5033472 + old: 2208152 = 7241624 Page faults: non-gc = 23 major + 0 minor, gc = 170 major + 0 minor [Started GC] scavenging...done Mark Pass...done(10,200+5,280), marked 1419214 objects, max depth = 47, cut 0 xfers. Weak-vector Pass...done(10+0). Cons-cell swap...done(40+20), 5435 cons cells moved Symbol-cell swap...done(20+0), 0 symbol cells moved Oldarea break chain...done(640+1,430), 322 holes totalling 3133104 bytes Page-compaction data...done(10+20). Address adjustment...done(10,920+3,380). Compacting other objects...done(920+550). Page compaction...done(30+270), 0 pages moved New rootset...done(4,320+2,900), 3975 rootset entries Building new pagemap...done(760+770). Merging empty oldspaces...done, 0 oldspaces merged. global gc recovered 3176824 bytes of old space. scavenging...done eff: 0%, copy new: 3544264 + old: 0 = 3544264 Page faults: non-gc = 48 major + 0 minor, gc = 27799 major + 0 minor [Finished GC] GC took 6.866667 minutes scavenging...done eff: 96%, copy new: 4995432 + old: 0 = 4995432 Page faults: non-gc = 657 major + 0 minor, gc = 308 major + 0 minor scavenging...done eff: 95%, copy new: 5113624 + old: 914712 = 6028336 Page faults: non-gc = 45 major + 0 minor, gc = 203 major + 0 minor scavenging...done eff: 94%, copy new: 5392120 + old: 798176 = 6190296 Page faults: non-gc = 4 major + 0 minor, gc = 165 major + 0 minor Set max update to 4668134 after LOAD scavenging...done eff: 93%, copy new: 5961600 + old: 531768 = 6493368 Page faults: non-gc = 2246 major + 0 minor, gc = 1540 major + 0 minor scavenging...done eff: 81%, copy new: 5656400 + old: 1401584 = 7057984 Page faults: non-gc = 1333 major + 0 minor, gc = 298 major + 0 minor scavenging...done eff: 83%, copy new: 4455832 + old: 1273400 = 5729232 Page faults: non-gc = 98 major + 0 minor, gc = 8 major + 0 minor scavenging...done eff: 85%, copy new: 4057368 + old: 444072 = 4501440 Page faults: non-gc = 213 major + 0 minor, gc = 4 major + 0 minor [Started GC] scavenging...done Mark Pass...done(12,810+6,920), marked 1557041 objects, max depth = 48, cut 0 xfers. Weak-vector Pass...done(0+10). Cons-cell swap...done(80+50), 4355 cons cells moved Symbol-cell swap...done(20+0), 0 symbol cells moved Oldarea break chain...done(900+1,690), 173 holes totalling 623160 bytes Page-compaction data...done(0+110). Address adjustment...done(11,990+5,520). Compacting other objects...done(610+90). Page compaction...done(30+380), 0 pages moved New rootset...done(4,790+4,770), 23601 rootset entries Building new pagemap...done(920+2,660). Merging empty oldspaces...done, 0 oldspaces merged. global gc recovered 658160 bytes of old space. scavenging...expanding old space...done eff: 0%, copy new: 3399232 + old: 658120 = 4057352 Page faults: non-gc = 318 major + 0 minor, gc = 44590 major + 0 minor [Finished GC] GC took 11.616667 minutes scavenging...done eff: 88%, copy new: 1310520 + old: 2183256 = 3493776 Page faults: non-gc = 1451 major + 0 minor, gc = 854 major + 0 minor scavenging...done eff: 95%, copy new: 1334000 + old: 43176 = 1377176 Page faults: non-gc = 1853 major + 0 minor, gc = 532 major + 0 minor Error: Received signal number 2 (Keyboard interrupt) [condition type: INTERRUPT-SIGNAL] Restart actions (select using :continue): 0: continue computation 1: Restart the ARIS/AR application 2: Reload all known patch files [1c] <cl> (room t) area address(bytes) cons symbols other bytes 8 bytes each 24 bytes each (free:used) (free:used) (free:used) Top #x4502000 New #x39fa000(11567104) 429:71920 253:1 7704016:3216408 New #x2ef2000(11567104) ----- ----- ----- Old #x2ab2000(4456448) 469:29082 0:0 2222760:1993776 Old #x98f50(44142768) 0:952765 226:65879 0:34864080 Tot (Old Areas) 469:981847 226:65879 2222760:36857856 Root pages: 479 code type items bytes 96: (SIMPLE-ARRAY T) 156436 21452648 43.4% 1: CONS 1050872 8406976 17.0% 108: (SIMPLE-ARRAY CODE) 13102 6181608 12.5% 101: (SIMPLE-ARRAY CHARACTER) 162670 5472968 11.1% 15: STRUCTURE 105449 3623336 7.3% 7: SYMBOL 65880 1581120 3.2% 8: FUNCTION 21636 1336536 2.7% 18: BIGNUM 82115 667272 1.3% 10: HASH-TABLE 8079 258528 0.5% 9: CLOSURE 12026 192416 0.4% 97: (SIMPLE-ARRAY BIT) 88 110520 0.2% 12: STANDARD-INSTANCE 5088 81408 0.2% 17: DOUBLE-FLOAT 3265 52240 0.1% 99: (SIMPLE-ARRAY (UNSIGNED-BYTE 16)) 75 28528 0.1% 16: SINGLE-FLOAT 2182 17456 0.0% 105: (SIMPLE-ARRAY (SIGNED-BYTE 16)) 6 8520 0.0% 98: (SIMPLE-ARRAY (UNSIGNED-BYTE 8)) 139 3840 0.0% 100: (SIMPLE-ARRAY (UNSIGNED-BYTE 32)) 63 2752 0.0% 65: (ARRAY BIT) 85 2040 0.0% 64: (ARRAY T) 33 792 0.0% 69: (ARRAY CHARACTER) 32 768 0.0% 19: RATIO 21 336 0.0% 20: COMPLEX 11 176 0.0% 11: READTABLE 8 128 0.0% 107: (SIMPLE-ARRAY (SIGNED-BYTE 32)) 2 104 0.0% 13: SYSVECTOR 2 32 0.0% total bytes = 49483048 malloc arena: max size free bytes used bytes total 8 888 1160 2048 24 1536 4608 6144 56 2800 784 3584 120 2280 1560 3840 504 4032 4032 8064 1016 4064 0 4064 2040 6120 14280 20400 4088 4088 0 4088 5112 20448 0 20448 9208 27624 9208 36832 total bytes: 73880 35632 109512 Reserved malloc space at #x89000: 61440 bytes reserved, 57344 bytes bucketed (4096 bytes unassigned) 45056 additional malloc bytes bucketed before reserved area ;;; ------ (asys::allegro-invoke-dynamic-gc) is our function which calls ;;; (excl:gc t) and prints the "[Started GC]" and time ;;; information. [1c] <cl> (asys::allegro-invoke-dynamic-gc) [Started GC] scavenging...done Mark Pass...done(12,870+5,920), marked 1565863 objects, max depth = 48, cut 0 xfers. Weak-vector Pass...done(0+0). Cons-cell swap...done(60+50), 1192 cons cells moved Symbol-cell swap...done(30+0), 0 symbol cells moved Oldarea break chain...done(930+1,720), 440 holes totalling 1116704 bytes Page-compaction data...done(30+150). Address adjustment...done(12,600+5,340). Compacting other objects...done(890+110). Page compaction...done(20+250), 31 pages moved New rootset...done(5,260+3,630), 7868 rootset entries Building new pagemap...done(800+1,190). Merging empty oldspaces...done, 0 oldspaces merged. global gc recovered 1124616 bytes of old space. scavenging...done eff: 28%, copy new: 1277528 + old: 0 = 1277528 Page faults: non-gc = 8090 major + 0 minor, gc = 36343 major + 0 minor [Finished GC] GC took 8.133333 minutes NIL [1c] <cl> (room t) area address(bytes) cons symbols other bytes 8 bytes each 24 bytes each (free:used) (free:used) (free:used) Top #x4502000 New #x39fa000(11567104) 735:17607 250:4 10154928:1199672 New #x2ef2000(11567104) ----- ----- ----- Old #x2ab2000(4456448) 0:0 0:0 2947104:1507000 Old #x98f50(44142768) 0:984354 226:65879 338464:34271664 Tot (Old Areas) 0:984354 226:65879 3285568:35778664 Root pages: 463 code type items bytes 96: (SIMPLE-ARRAY T) 151939 20322936 43.7% 1: CONS 998930 7991440 17.2% 108: (SIMPLE-ARRAY CODE) 13101 6181240 13.3% 101: (SIMPLE-ARRAY CHARACTER) 121183 4428976 9.5% 15: STRUCTURE 101440 3464736 7.4% 7: SYMBOL 65883 1581192 3.4% 8: FUNCTION 21636 1336496 2.9% 18: BIGNUM 66130 537424 1.2% 10: HASH-TABLE 8079 258528 0.6% 9: CLOSURE 8697 139152 0.3% 97: (SIMPLE-ARRAY BIT) 88 110520 0.2% 12: STANDARD-INSTANCE 5088 81408 0.2% 17: DOUBLE-FLOAT 3258 52128 0.1% 99: (SIMPLE-ARRAY (UNSIGNED-BYTE 16)) 75 28528 0.1% 16: SINGLE-FLOAT 1105 8840 0.0% 105: (SIMPLE-ARRAY (SIGNED-BYTE 16)) 6 8520 0.0% 98: (SIMPLE-ARRAY (UNSIGNED-BYTE 8)) 139 3840 0.0% 100: (SIMPLE-ARRAY (UNSIGNED-BYTE 32)) 63 2752 0.0% 65: (ARRAY BIT) 85 2040 0.0% 64: (ARRAY T) 33 792 0.0% 69: (ARRAY CHARACTER) 32 768 0.0% 19: RATIO 17 272 0.0% 20: COMPLEX 11 176 0.0% 11: READTABLE 8 128 0.0% 107: (SIMPLE-ARRAY (SIGNED-BYTE 32)) 2 104 0.0% 13: SYSVECTOR 2 32 0.0% total bytes = 46542968 malloc arena: max size free bytes used bytes total 8 888 1160 2048 24 1536 4608 6144 56 2800 784 3584 120 2280 1560 3840 504 4032 4032 8064 1016 4064 0 4064 2040 6120 14280 20400 4088 4088 0 4088 5112 20448 0 20448 9208 27624 9208 36832 total bytes: 73880 35632 109512 Reserved malloc space at #x89000: 61440 bytes reserved, 57344 bytes bucketed (4096 bytes unassigned) 45056 additional malloc bytes bucketed before reserved area [1c] <cl> :cont 0 ===================================================================== End of message --LAA16592.840642066/khyber.ascent.com-- |