runsolver Copyright (C) 2010 Olivier ROUSSEL This is runsolver version 3.2.9a (svn: 651) This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. command line: runsolver -W 300 -M 1124 -w /home/cbse/results/sarge-etch-lenny-squeeze-sid/logs/71.runsolver.aptitude aptitude -s -y --without-recommends install spread libffcall1 mirror gcompris cvstrac Enforcing wall clock limit (soft limit, will send signal-name then SIGKILL): 300 seconds Enforcing VSIZE limit (soft limit, will send signal-name then SIGKILL): 1150976 KiB Enforcing VSIZE limit (hard limit, stack expansion will fail with SIGSEGV, brk() and mmap() will return ENOMEM): 1202176 KiB Current StackSize limit: 8192 KiB [startup+0 s] /proc/loadavg: 1.35 1.14 1.08 2/55 26075 /proc/meminfo: memFree=952392/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=3152 CPUtime=0 /proc/26075/stat : 26075 (runsolver) R 26074 26075 17863 34816 17863 4202560 77 0 0 0 0 0 0 0 20 0 1 0 29700125 3227648 98 18446744073709551615 134512640 134586868 4287754912 4287752936 4149674911 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/26075/statm: 788 98 66 19 0 73 0 [startup+0.133717 s] /proc/loadavg: 1.35 1.14 1.08 2/55 26075 /proc/meminfo: memFree=952392/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=25980 CPUtime=0 /proc/26075/stat : 26075 (aptitude) D 26074 26075 17863 34816 17863 4202496 151 0 10 0 0 0 0 0 20 0 1 0 29700125 26603520 73 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188271672 140188617061142 0 0 0 0 0 0 0 17 0 0 0 11 0 0 /proc/26075/statm: 6495 73 48 1052 0 32 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 25980 [startup+0.20041 s] /proc/loadavg: 1.35 1.14 1.08 2/55 26075 /proc/meminfo: memFree=952392/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=38696 CPUtime=0 /proc/26075/stat : 26075 (aptitude) D 26074 26075 17863 34816 17863 4202496 174 0 15 0 0 0 0 0 20 0 1 0 29700125 39624704 97 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188271336 140188617061110 0 0 0 0 0 0 0 17 0 0 0 18 0 0 /proc/26075/statm: 9674 97 61 1052 0 60 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 38696 [startup+0.300392 s] /proc/loadavg: 1.35 1.14 1.08 2/55 26075 /proc/meminfo: memFree=952392/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=54968 CPUtime=0 /proc/26075/stat : 26075 (aptitude) D 26074 26075 17863 34816 17863 4202496 1088 0 25 0 0 0 0 0 20 0 1 0 29700125 56287232 1003 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188271048 140188577047808 0 134217728 4096 0 0 0 0 17 0 0 0 28 0 0 /proc/26075/statm: 13742 1003 833 1052 0 106 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 54968 [startup+0.7003 s] /proc/loadavg: 1.35 1.14 1.08 2/55 26075 /proc/meminfo: memFree=952392/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=103288 CPUtime=0.02 /proc/26075/stat : 26075 (aptitude) D 26074 26075 17863 34816 17863 4202496 2720 1706 79 2 0 2 0 0 20 0 1 0 29700125 105766912 2600 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188266480 140188614252442 0 134217728 4096 0 0 0 0 17 0 0 0 64 0 0 /proc/26075/statm: 25822 2600 1388 1052 0 1159 0 Current children cumulated CPU time (s) 0.02 Current children cumulated vsize (KiB) 103288 [startup+1.50034 s] /proc/loadavg: 1.35 1.14 1.08 1/56 26079 /proc/meminfo: memFree=943332/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=103288 CPUtime=0.03 /proc/26075/stat : 26075 (aptitude) D 26074 26075 17863 34816 17863 4202496 4419 1706 209 2 0 3 0 0 20 0 1 0 29700125 105766912 4429 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188266480 140188614252442 0 134217728 4096 0 0 0 0 17 0 0 0 144 0 0 /proc/26075/statm: 25822 4429 3217 1052 0 1159 0 Current children cumulated CPU time (s) 0.03 Current children cumulated vsize (KiB) 103288 [startup+3.10021 s] /proc/loadavg: 1.33 1.14 1.08 2/56 26079 /proc/meminfo: memFree=941100/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=123068 CPUtime=0.65 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 17363 1706 321 2 52 13 0 0 20 0 1 0 29700125 126021632 15961 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188264440 140188587958640 0 134217728 4096 0 0 0 0 17 0 0 0 243 0 0 /proc/26075/statm: 30767 15961 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.65 Current children cumulated vsize (KiB) 123068 heavy processes: [startup+6.30025 s] /proc/loadavg: 1.33 1.14 1.08 2/58 26081 /proc/meminfo: memFree=804808/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=137796 CPUtime=3.25 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 21651 2203 321 4 301 24 0 0 20 0 2 0 29700125 141103104 17926 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188261712 140188614030380 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 299 0 0 /proc/26075/statm: 34449 17926 10303 1052 0 9786 0 [pid=26075/tid=26080] ppid=26074 vsize=137796 CPUtime=0 /proc/26075/task/26080/stat : 26080 (aptitude) S 26074 26075 17863 34816 17863 4202560 6 2203 0 4 0 0 0 0 20 0 2 0 29700510 141103104 17926 18446744073709551615 140188619202560 140188623509912 140736188275008 140188506880000 140188587946708 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.25 Current children cumulated vsize (KiB) 137796 heavy processes: [startup+12.7002 s] /proc/loadavg: 1.27 1.13 1.07 2/57 26081 /proc/meminfo: memFree=735872/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=275356 CPUtime=9.61 /proc/26075/stat : 26075 (aptitude) S 26074 26075 17863 34816 17863 4202496 40506 2203 321 4 928 33 0 0 20 0 2 0 29700125 281964544 36173 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188266768 140188587947595 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 299 0 0 /proc/26075/statm: 68839 36173 10359 1052 0 44176 0 [pid=26075/tid=26080] ppid=26074 vsize=275356 CPUtime=6.13 /proc/26075/task/26080/stat : 26080 (aptitude) R 26074 26075 17863 34816 17863 4202560 18854 2203 0 4 604 9 0 0 20 0 2 0 29700510 281964544 36173 18446744073709551615 140188619202560 140188623509912 140736188275008 140188506871320 140188621835687 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 9.61 Current children cumulated vsize (KiB) 275356 heavy processes: [startup+25.5003 s] /proc/loadavg: 1.23 1.13 1.07 1/57 26081 /proc/meminfo: memFree=658124/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=348140 CPUtime=22.24 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 59269 2203 334 4 2180 44 0 0 20 0 2 0 29700125 356495360 54525 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188265144 140188621804496 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 307 0 0 /proc/26075/statm: 87035 54525 10409 1052 0 62365 0 [pid=26075/tid=26080] ppid=26074 vsize=348140 CPUtime=18.62 /proc/26075/task/26080/stat : 26080 (aptitude) S 26074 26075 17863 34816 17863 4202560 37418 2203 1 4 1842 20 0 0 20 0 2 0 29700510 356495360 54525 18446744073709551615 140188619202560 140188623509912 140736188275008 140188506880000 140188587946708 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 22.24 Current children cumulated vsize (KiB) 348140 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.23 1.13 1.07 1/57 26081 /proc/meminfo: memFree=658124/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=348176 CPUtime=22.34 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 59289 2203 334 4 2190 44 0 0 20 0 2 0 29700125 356532224 54545 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188265144 140188576693931 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 307 0 0 /proc/26075/statm: 87044 54545 10409 1052 0 62374 0 [pid=26075/tid=26080] ppid=26074 vsize=348176 CPUtime=18.62 /proc/26075/task/26080/stat : 26080 (aptitude) S 26074 26075 17863 34816 17863 4202560 37418 2203 1 4 1842 20 0 0 20 0 2 0 29700510 356532224 54545 18446744073709551615 140188619202560 140188623509912 140736188275008 140188506880000 140188587946708 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 22.34 Current children cumulated vsize (KiB) 348176 [startup+26.0002 s] /proc/loadavg: 1.23 1.13 1.07 1/57 26081 /proc/meminfo: memFree=658124/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=348176 CPUtime=22.74 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 61918 2203 334 4 2229 45 0 0 20 0 2 0 29700125 356532224 54594 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188266712 140188614089723 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 307 0 0 /proc/26075/statm: 87044 54594 10410 1052 0 62374 0 [pid=26075/tid=26080] ppid=26074 vsize=348176 CPUtime=18.62 /proc/26075/task/26080/stat : 26080 (aptitude) S 26074 26075 17863 34816 17863 4202560 37418 2203 1 4 1842 20 0 0 20 0 2 0 29700510 356532224 54594 18446744073709551615 140188619202560 140188623509912 140736188275008 140188506880000 140188587946708 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 22.74 Current children cumulated vsize (KiB) 348176 [startup+26.2002 s] /proc/loadavg: 1.23 1.13 1.07 1/57 26081 /proc/meminfo: memFree=658124/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=348176 CPUtime=22.95 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 62173 2703 334 4 2241 52 1 1 20 0 2 0 29700125 356532224 54710 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188265256 140188614311027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 307 0 0 /proc/26075/statm: 87044 54710 10410 1052 0 62374 0 [pid=26075/tid=26080] ppid=26074 vsize=348176 CPUtime=18.64 /proc/26075/task/26080/stat : 26080 (aptitude) S 26074 26075 17863 34816 17863 4202560 37418 2703 1 4 1842 20 1 1 20 0 2 0 29700510 356532224 54710 18446744073709551615 140188619202560 140188623509912 140736188275008 140188506880000 140188587946708 0 134217728 4096 0 0 0 0 -1 0 0 0 2 0 0 Current children cumulated CPU time (s) 22.95 Current children cumulated vsize (KiB) 348176 [startup+26.3003 s] /proc/loadavg: 1.23 1.13 1.07 1/57 26081 /proc/meminfo: memFree=658124/1022884 swapFree=0/0 [pid=26075] ppid=26074 vsize=327420 CPUtime=23.04 /proc/26075/stat : 26075 (aptitude) R 26074 26075 17863 34816 17863 4202496 62631 2703 336 4 2245 57 1 1 20 0 1 0 29700125 335278080 30879 18446744073709551615 140188619202560 140188623509912 140736188275008 140736188272056 140188577068522 0 134217728 4096 0 0 0 0 17 0 0 0 308 0 0 /proc/26075/statm: 81855 30879 10413 1052 0 57185 0 Current children cumulated CPU time (s) 23.04 Current children cumulated vsize (KiB) 327420 Child status: 0 Real time (s): 26.3965 CPU time (s): 23.0894 CPU user time (s): 22.4774 CPU system time (s): 0.612038 CPU usage (%): 87.4716 Max. virtual memory (cumulated for all children) (KiB): 348176 getrusage(RUSAGE_CHILDREN,...) data: user time used= 22.4774 system time used= 0.612038 maximum resident set size= 218956 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 65428 page faults= 355 swaps= 0 block input operations= 238576 block output operations= 144 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 2398 involuntary context switches= 438 runsolver used 0.024001 second user time and 0.112007 second system time The end