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/37.runsolver.aptitude aptitude -s -y --without-recommends install python-uncertainities libcfitsio2 contact-lookup-applet python-imaging-doc xfce4 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.00 1.04 1.02 2/55 25311 /proc/meminfo: memFree=832048/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=3152 CPUtime=0 /proc/25311/stat : 25311 (runsolver) R 25310 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29466796 3227648 32 18446744073709551615 134512640 134586868 4290775888 4290773936 4151829552 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.207871 s] /proc/loadavg: 1.00 1.04 1.02 2/55 25311 /proc/meminfo: memFree=832048/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=103288 CPUtime=0.19 /proc/25311/stat : 25311 (aptitude) R 25310 25311 17863 34816 17863 4202496 11302 1709 0 0 17 2 0 0 20 0 1 0 29466796 105766912 11103 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325200 140470844124733 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 25822 11103 9892 1052 0 1159 0 Current children cumulated CPU time (s) 0.19 Current children cumulated vsize (KiB) 103288 [startup+0.300268 s] /proc/loadavg: 1.00 1.04 1.02 2/55 25311 /proc/meminfo: memFree=832048/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=114256 CPUtime=0.28 /proc/25311/stat : 25311 (aptitude) R 25310 25311 17863 34816 17863 4202496 14137 1709 0 0 25 3 0 0 20 0 1 0 29466796 116998144 13930 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325584 140470850875997 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 28564 13930 9961 1052 0 3901 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 114256 [startup+0.400264 s] /proc/loadavg: 1.00 1.04 1.02 2/55 25311 /proc/meminfo: memFree=832048/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=120696 CPUtime=0.39 /proc/25311/stat : 25311 (aptitude) R 25310 25311 17863 34816 17863 4202496 17094 1709 0 0 35 4 0 0 20 0 1 0 29466796 123592704 15371 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312323448 140470851663833 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 30174 15371 9972 1052 0 5511 0 Current children cumulated CPU time (s) 0.39 Current children cumulated vsize (KiB) 120696 [startup+0.700187 s] /proc/loadavg: 1.00 1.04 1.02 2/55 25311 /proc/meminfo: memFree=832048/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=123068 CPUtime=0.69 /proc/25311/stat : 25311 (aptitude) R 25310 25311 17863 34816 17863 4202496 17687 1709 0 0 62 7 0 0 20 0 1 0 29466796 126021632 15964 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312323368 140470806265346 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 30767 15964 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 123068 [startup+1.50023 s] /proc/loadavg: 1.00 1.04 1.02 2/57 25316 /proc/meminfo: memFree=802528/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=136340 CPUtime=1.48 /proc/25311/stat : 25311 (aptitude) R 25310 25311 17863 34816 17863 4202496 20782 1709 0 0 140 8 0 0 20 0 2 0 29466796 139612160 17699 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312324288 140470851716108 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 34085 17699 10244 1052 0 9422 0 [pid=25311/tid=25316] ppid=25310 vsize=136340 CPUtime=0 /proc/25311/task/25316/stat : 25316 (aptitude) S 25310 25311 17863 34816 17863 4202560 4 1709 0 0 0 0 0 0 20 0 2 0 29466866 139612160 17699 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736402432 140470817469140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 136340 [startup+3.10024 s] /proc/loadavg: 1.00 1.04 1.02 2/57 25317 /proc/meminfo: memFree=801280/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=137836 CPUtime=3.07 /proc/25311/stat : 25311 (aptitude) R 25310 25311 17863 34816 17863 4202496 21993 2211 0 0 294 13 0 0 20 0 2 0 29466796 141144064 17940 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312320640 140470806235288 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 34459 17940 10303 1052 0 9796 0 [pid=25311/tid=25316] ppid=25310 vsize=137836 CPUtime=0 /proc/25311/task/25316/stat : 25316 (aptitude) S 25310 25311 17863 34816 17863 4202560 6 2211 0 0 0 0 0 0 20 0 2 0 29466866 141144064 17940 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736402432 140470817469140 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.07 Current children cumulated vsize (KiB) 137836 [startup+6.30024 s] /proc/loadavg: 1.00 1.04 1.02 2/57 25317 /proc/meminfo: memFree=756152/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=254336 CPUtime=6.25 /proc/25311/stat : 25311 (aptitude) S 25310 25311 17863 34816 17863 4202496 35528 2211 0 0 605 20 0 0 20 0 2 0 29466796 260440064 30915 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325696 140470817470027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 63584 30915 10359 1052 0 38921 0 [pid=25311/tid=25316] ppid=25310 vsize=254336 CPUtime=2.97 /proc/25311/task/25316/stat : 25316 (aptitude) R 25310 25311 17863 34816 17863 4202560 13534 2211 0 0 290 7 0 0 20 0 2 0 29466866 260440064 30915 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736396568 140470806235232 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.25 Current children cumulated vsize (KiB) 254336 [startup+12.7002 s] /proc/loadavg: 1.00 1.04 1.02 2/57 25317 /proc/meminfo: memFree=700476/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=306444 CPUtime=12.62 /proc/25311/stat : 25311 (aptitude) S 25310 25311 17863 34816 17863 4202496 48705 2211 0 0 1239 23 0 0 20 0 2 0 29466796 313798656 43933 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325696 140470817470027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 76611 43933 10359 1052 0 51948 0 [pid=25311/tid=25316] ppid=25310 vsize=306444 CPUtime=9.34 /proc/25311/task/25316/stat : 25316 (aptitude) R 25310 25311 17863 34816 17863 4202560 26711 2211 0 0 924 10 0 0 20 0 2 0 29466866 313798656 43933 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736393752 140470851371290 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.62 Current children cumulated vsize (KiB) 306444 [startup+25.5032 s] /proc/loadavg: 1.00 1.03 1.02 2/57 25317 /proc/meminfo: memFree=632764/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=371388 CPUtime=25.36 /proc/25311/stat : 25311 (aptitude) S 25310 25311 17863 34816 17863 4202496 65644 2211 0 0 2502 34 0 0 20 0 2 0 29466796 380301312 60176 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325696 140470817470027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 92847 60176 10360 1052 0 68184 0 [pid=25311/tid=25316] ppid=25310 vsize=371388 CPUtime=22.07 /proc/25311/task/25316/stat : 25316 (aptitude) R 25310 25311 17863 34816 17863 4202560 43650 2211 0 0 2187 20 0 0 20 0 2 0 29466866 380301312 60176 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736393752 140470851355280 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 371388 [startup+51.1003 s] /proc/loadavg: 1.00 1.03 1.01 2/57 25317 /proc/meminfo: memFree=484832/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=520772 CPUtime=50.83 /proc/25311/stat : 25311 (aptitude) S 25310 25311 17863 34816 17863 4202496 103105 2211 0 0 5032 51 0 0 20 0 2 0 29466796 533270528 97495 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325696 140470817470027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 130193 97495 10360 1052 0 105530 0 [pid=25311/tid=25316] ppid=25310 vsize=520772 CPUtime=47.55 /proc/25311/task/25316/stat : 25316 (aptitude) R 25310 25311 17863 34816 17863 4202560 81111 2211 0 0 4717 38 0 0 20 0 2 0 29466866 533270528 97495 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736395960 140470851526969 0 134217728 4096 0 0 0 0 -1 0 0 0 1 0 0 Current children cumulated CPU time (s) 50.83 Current children cumulated vsize (KiB) 520772 [startup+102.3 s] /proc/loadavg: 1.00 1.02 1.01 2/57 25317 /proc/meminfo: memFree=25404/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=984768 CPUtime=101.78 /proc/25311/stat : 25311 (aptitude) S 25310 25311 17863 34816 17863 4202496 219019 2211 0 0 10066 112 0 0 20 0 2 0 29466796 1008402432 213386 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325696 140470817470027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 246192 213386 10375 1052 0 221529 0 [pid=25311/tid=25316] ppid=25310 vsize=984768 CPUtime=98.49 /proc/25311/task/25316/stat : 25316 (aptitude) R 25310 25311 17863 34816 17863 4202560 197019 2211 0 0 9751 98 0 0 20 0 2 0 29466866 1008402432 213386 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736394104 140470851358152 0 134217728 4096 0 0 0 0 -1 0 0 0 3 0 0 Current children cumulated CPU time (s) 101.78 Current children cumulated vsize (KiB) 984768 Maximum VSize exceeded: sending signal-name then SIGKILL [startup+124.6 s] /proc/loadavg: 1.21 1.07 1.02 2/57 25317 /proc/meminfo: memFree=9292/1022884 swapFree=0/0 [pid=25311] ppid=25310 vsize=1151232 CPUtime=121.96 /proc/25311/stat : 25311 (aptitude) S 25310 25311 17863 34816 17863 4202496 260718 2211 140 0 12049 147 0 0 20 0 2 0 29466796 1178861568 246482 18446744073709551615 140470848724992 140470853032344 140737312333936 140737312325696 140470817470027 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25311/statm: 287808 246482 10269 1052 0 263145 0 [pid=25311/tid=25316] ppid=25310 vsize=1151232 CPUtime=118.67 /proc/25311/task/25316/stat : 25316 (aptitude) R 25310 25311 17863 34816 17863 4202560 238718 2211 140 0 11734 133 0 0 20 0 2 0 29466866 1178861568 246482 18446744073709551615 140470848724992 140470853032344 140737312333936 140470736393752 140470843423505 0 134217728 4096 0 0 0 0 -1 0 0 0 173 0 0 Current children cumulated CPU time (s) 121.96 Current children cumulated vsize (KiB) 1151232 Sending Terminated to process tree (bottom up) Sleeping 2 seconds Solver just ended. Dumping a history of the last processes samples Child ended because it received signal 15 (SIGTERM) Real time (s): 124.724 CPU time (s): 122.108 CPU user time (s): 120.56 CPU system time (s): 1.5481 CPU usage (%): 97.9019 Max. virtual memory (cumulated for all children) (KiB): 1151232 getrusage(RUSAGE_CHILDREN,...) data: user time used= 120.56 system time used= 1.5481 maximum resident set size= 986336 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 263031 page faults= 140 swaps= 0 block input operations= 3224 block output operations= 72 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 472 involuntary context switches= 2746 runsolver used 0.216013 second user time and 0.368023 second system time The end