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/39.runsolver.aptitude aptitude -s -y --without-recommends install libselinux1 rcs guile-gnome0-gnome-ui nettle-bin libopenssl-ruby1.6 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 [startup+0 s] /proc/loadavg: 1.51 1.16 1.05 2/55 25553 /proc/meminfo: memFree=749796/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=3152 CPUtime=0 /proc/25553/stat : 25553 (runsolver) R 25552 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29482426 3227648 33 18446744073709551615 134512640 134586868 4290746688 4290744736 4151866416 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 788 33 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.171047 s] /proc/loadavg: 1.51 1.16 1.05 2/55 25553 /proc/meminfo: memFree=749796/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=103288 CPUtime=0.16 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 11289 1709 0 0 13 2 1 0 20 0 1 0 29482426 105766912 11090 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012448 140336728979197 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 25822 11090 9879 1052 0 1159 0 Current children cumulated CPU time (s) 0.16 Current children cumulated vsize (KiB) 103288 [startup+0.200285 s] /proc/loadavg: 1.51 1.16 1.05 2/55 25553 /proc/meminfo: memFree=749796/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=103288 CPUtime=0.19 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 11299 1709 0 0 16 2 1 0 20 0 1 0 29482426 105766912 11100 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012448 140336729533984 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 25822 11100 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 103288 [startup+0.300387 s] /proc/loadavg: 1.51 1.16 1.05 2/55 25553 /proc/meminfo: memFree=749796/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=103432 CPUtime=0.29 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 11426 1709 0 0 26 2 1 0 20 0 1 0 29482426 105914368 11219 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452010960 140336728987618 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 25858 11219 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.29 Current children cumulated vsize (KiB) 103432 [startup+0.700277 s] /proc/loadavg: 1.51 1.16 1.05 2/55 25553 /proc/meminfo: memFree=749796/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=123068 CPUtime=0.69 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 17687 1709 0 0 60 8 1 0 20 0 1 0 29482426 126021632 15964 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452010616 140336729034896 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 30767 15964 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 123068 [startup+1.50026 s] /proc/loadavg: 1.51 1.16 1.05 2/57 25558 /proc/meminfo: memFree=729824/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=136044 CPUtime=1.49 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 20638 1709 0 0 138 10 1 0 20 0 2 0 29482426 139309056 17558 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012456 140336700443264 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 34011 17558 10207 1052 0 9348 0 [pid=25553/tid=25558] ppid=25552 vsize=136044 CPUtime=0.01 /proc/25553/task/25558/stat : 25558 (aptitude) S 25552 25553 17863 34816 17863 4202560 4 1709 0 0 0 0 1 0 20 0 2 0 29482503 139309056 17558 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621811712 140336702878420 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 136044 [startup+3.10038 s] /proc/loadavg: 1.47 1.15 1.05 2/57 25558 /proc/meminfo: memFree=719656/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=137800 CPUtime=3.08 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 21981 2209 0 0 290 17 1 0 20 0 2 0 29482426 141107200 17927 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452007888 140336736710437 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 34450 17927 10303 1052 0 9787 0 [pid=25553/tid=25558] ppid=25552 vsize=137800 CPUtime=0.01 /proc/25553/task/25558/stat : 25558 (aptitude) S 25552 25553 17863 34816 17863 4202560 6 2209 0 0 0 0 1 0 20 0 2 0 29482503 141107200 17927 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621811712 140336702878420 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 137800 [startup+6.30026 s] /proc/loadavg: 1.47 1.15 1.05 2/57 25559 /proc/meminfo: memFree=677620/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=251284 CPUtime=6.27 /proc/25553/stat : 25553 (aptitude) S 25552 25553 17863 34816 17863 4202496 34736 2209 0 0 606 20 1 0 20 0 2 0 29482426 257314816 30145 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012944 140336702879307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 62821 30145 10359 1052 0 38158 0 [pid=25553/tid=25558] ppid=25552 vsize=251284 CPUtime=2.87 /proc/25553/task/25558/stat : 25558 (aptitude) R 25552 25553 17863 34816 17863 4202560 12754 2209 0 0 283 3 1 0 20 0 2 0 29482503 257314816 30145 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621802984 140336736832233 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 251284 [startup+12.7003 s] /proc/loadavg: 1.39 1.15 1.05 2/57 25559 /proc/meminfo: memFree=630128/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=296676 CPUtime=12.63 /proc/25553/stat : 25553 (aptitude) S 25552 25553 17863 34816 17863 4202496 46469 2209 0 0 1235 27 1 0 20 0 2 0 29482426 303796224 41477 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012944 140336702879307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 74169 41477 10360 1052 0 49506 0 [pid=25553/tid=25558] ppid=25552 vsize=296676 CPUtime=9.24 /proc/25553/task/25558/stat : 25558 (aptitude) R 25552 25553 17863 34816 17863 4202560 24487 2209 0 0 913 10 1 0 20 0 2 0 29482503 303796224 41477 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621803032 140336692286675 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.63 Current children cumulated vsize (KiB) 296676 Solver just ended. Dumping a history of the last processes samples [startup+12.8004 s] /proc/loadavg: 1.39 1.15 1.05 2/57 25559 /proc/meminfo: memFree=630128/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=297072 CPUtime=12.73 /proc/25553/stat : 25553 (aptitude) S 25552 25553 17863 34816 17863 4202496 46585 2209 0 0 1245 27 1 0 20 0 2 0 29482426 304201728 41593 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012944 140336702879307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 74268 41593 10360 1052 0 49605 0 [pid=25553/tid=25558] ppid=25552 vsize=297072 CPUtime=9.34 /proc/25553/task/25558/stat : 25558 (aptitude) R 25552 25553 17863 34816 17863 4202560 24603 2209 0 0 923 10 1 0 20 0 2 0 29482503 304201728 41593 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621804640 140336700042656 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.73 Current children cumulated vsize (KiB) 297072 [startup+19.2003 s] /proc/loadavg: 1.36 1.15 1.05 2/57 25559 /proc/meminfo: memFree=586480/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=337084 CPUtime=19.1 /proc/25553/stat : 25553 (aptitude) S 25552 25553 17863 34816 17863 4202496 56616 2209 0 0 1875 34 1 0 20 0 2 0 29482426 345174016 51595 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012944 140336702879307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 84271 51595 10360 1052 0 59608 0 [pid=25553/tid=25558] ppid=25552 vsize=337084 CPUtime=15.71 /proc/25553/task/25558/stat : 25558 (aptitude) R 25552 25553 17863 34816 17863 4202560 34634 2209 0 0 1553 17 1 0 20 0 2 0 29482503 345174016 51595 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621803032 140336700439532 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 19.1 Current children cumulated vsize (KiB) 337084 [startup+22.4003 s] /proc/loadavg: 1.33 1.14 1.05 2/57 25559 /proc/meminfo: memFree=569864/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=353140 CPUtime=22.29 /proc/25553/stat : 25553 (aptitude) S 25552 25553 17863 34816 17863 4202496 60647 2209 0 0 2192 36 1 0 20 0 2 0 29482426 361615360 55596 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452012944 140336702879307 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 88285 55596 10360 1052 0 63622 0 [pid=25553/tid=25558] ppid=25552 vsize=353140 CPUtime=18.89 /proc/25553/task/25558/stat : 25558 (aptitude) R 25552 25553 17863 34816 17863 4202560 38665 2209 0 0 1869 19 1 0 20 0 2 0 29482503 361615360 55596 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621805192 140336691644810 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 22.29 Current children cumulated vsize (KiB) 353140 [startup+23.2032 s] /proc/loadavg: 1.33 1.14 1.05 2/57 25559 /proc/meminfo: memFree=565028/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=355676 CPUtime=23.08 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 61491 2209 0 0 2270 37 1 0 20 0 2 0 29482426 364212224 56384 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452011320 140336736736544 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 88919 56384 10408 1052 0 64249 0 [pid=25553/tid=25558] ppid=25552 vsize=355676 CPUtime=19.57 /proc/25553/task/25558/stat : 25558 (aptitude) S 25552 25553 17863 34816 17863 4202560 39295 2209 0 0 1936 20 1 0 20 0 2 0 29482503 364212224 56384 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621811712 140336702878420 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 23.08 Current children cumulated vsize (KiB) 355676 [startup+23.6003 s] /proc/loadavg: 1.33 1.14 1.05 2/57 25559 /proc/meminfo: memFree=565028/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=355704 CPUtime=23.48 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 62329 2209 0 0 2310 37 1 0 20 0 2 0 29482426 364240896 56404 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452009048 140336691644656 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 88926 56404 10409 1052 0 64256 0 [pid=25553/tid=25558] ppid=25552 vsize=355704 CPUtime=19.57 /proc/25553/task/25558/stat : 25558 (aptitude) S 25552 25553 17863 34816 17863 4202560 39295 2209 0 0 1936 20 1 0 20 0 2 0 29482503 364240896 56404 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621811712 140336702878420 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 23.48 Current children cumulated vsize (KiB) 355704 [startup+24.0004 s] /proc/loadavg: 1.33 1.14 1.05 2/57 25559 /proc/meminfo: memFree=565028/1022884 swapFree=0/0 [pid=25553] ppid=25552 vsize=355704 CPUtime=23.86 /proc/25553/stat : 25553 (aptitude) R 25552 25553 17863 34816 17863 4202496 64458 2710 0 0 2340 45 1 0 20 0 2 0 29482426 364240896 56355 18446744073709551615 140336734134272 140336738441624 140734452021184 140734452013000 140336691978309 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25553/statm: 88926 56355 10409 1052 0 64256 0 [pid=25553/tid=25558] ppid=25552 vsize=355704 CPUtime=19.57 /proc/25553/task/25558/stat : 25558 (aptitude) S 25552 25553 17863 34816 17863 4202560 39295 2710 0 0 1936 20 1 0 20 0 2 0 29482503 364240896 56355 18446744073709551615 140336734134272 140336738441624 140734452021184 140336621811712 140336702878420 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 23.86 Current children cumulated vsize (KiB) 355704 Child status: 0 Real time (s): 24.0785 CPU time (s): 23.9655 CPU user time (s): 23.4375 CPU system time (s): 0.528033 CPU usage (%): 99.5306 Max. virtual memory (cumulated for all children) (KiB): 355704 getrusage(RUSAGE_CHILDREN,...) data: user time used= 23.4375 system time used= 0.528033 maximum resident set size= 226380 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 67679 page faults= 0 swaps= 0 block input operations= 0 block output operations= 144 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 103 involuntary context switches= 465 runsolver used 0.020001 second user time and 0.100006 second system time The end