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/52.runsolver.aptitude aptitude -s -y --without-recommends install libsqlrelay-ruby python-biopython-martel mird1 med-imaging libginac-dev 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.08 1.07 1.05 2/55 25670 /proc/meminfo: memFree=834608/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=3152 CPUtime=0 /proc/25670/stat : 25670 (runsolver) R 25669 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 29571797 3227648 32 18446744073709551615 134512640 134586868 4289452448 4289450496 4151845936 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 788 32 0 19 0 73 0 [startup+0.19968 s] /proc/loadavg: 1.08 1.07 1.05 2/55 25670 /proc/meminfo: memFree=834608/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=103288 CPUtime=0.2 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 11300 1709 0 0 17 2 1 0 20 0 1 0 29571797 105766912 11102 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274616800 139669587762042 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 25822 11102 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 103288 [startup+0.200275 s] /proc/loadavg: 1.08 1.07 1.05 2/55 25670 /proc/meminfo: memFree=834608/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=103288 CPUtime=0.2 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 11300 1709 0 0 17 2 1 0 20 0 1 0 29571797 105766912 11102 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274616800 139669550517995 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 25822 11102 9889 1052 0 1159 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 103288 [startup+0.300185 s] /proc/loadavg: 1.08 1.07 1.05 2/55 25670 /proc/meminfo: memFree=834608/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=103432 CPUtime=0.3 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 11427 1709 0 0 27 2 1 0 20 0 1 0 29571797 105914368 11221 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274615312 139669587789794 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 25858 11221 9956 1052 0 1195 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 103432 [startup+0.7002 s] /proc/loadavg: 1.08 1.07 1.05 2/55 25670 /proc/meminfo: memFree=834608/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=123068 CPUtime=0.69 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 17688 1709 0 0 62 6 1 0 20 0 1 0 29571797 126021632 15966 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274614968 139669587837076 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 30767 15966 9976 1052 0 6104 0 Current children cumulated CPU time (s) 0.69 Current children cumulated vsize (KiB) 123068 [startup+1.50024 s] /proc/loadavg: 1.08 1.07 1.05 2/57 25675 /proc/meminfo: memFree=814636/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=136060 CPUtime=1.49 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 20644 1709 0 0 141 7 1 0 20 0 2 0 29571797 139325440 17563 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274616808 139669550446919 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 34015 17563 10207 1052 0 9352 0 [pid=25670/tid=25675] ppid=25669 vsize=136060 CPUtime=0.01 /proc/25670/task/25675/stat : 25675 (aptitude) S 25669 25670 17863 34816 17863 4202560 4 1709 0 0 0 0 1 0 20 0 2 0 29571874 139325440 17563 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480613888 139669561680596 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) 136060 [startup+3.10024 s] /proc/loadavg: 1.08 1.07 1.05 2/57 25675 /proc/meminfo: memFree=804344/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=137820 CPUtime=3.08 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 21995 2207 0 0 292 15 1 0 20 0 2 0 29571797 141127680 17937 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274612240 139669550447055 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 34455 17937 10303 1052 0 9792 0 [pid=25670/tid=25675] ppid=25669 vsize=137820 CPUtime=0.01 /proc/25670/task/25675/stat : 25675 (aptitude) S 25669 25670 17863 34816 17863 4202560 6 2207 0 0 0 0 1 0 20 0 2 0 29571874 141127680 17937 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480613888 139669561680596 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) 137820 [startup+6.30023 s] /proc/loadavg: 1.16 1.09 1.05 2/57 25676 /proc/meminfo: memFree=765408/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=252636 CPUtime=6.26 /proc/25670/stat : 25670 (aptitude) S 25669 25670 17863 34816 17863 4202496 34822 2207 0 0 606 19 1 0 20 0 2 0 29571797 258699264 30482 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274617296 139669561681483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 63159 30482 10359 1052 0 38496 0 [pid=25670/tid=25675] ppid=25669 vsize=252636 CPUtime=2.88 /proc/25670/task/25675/stat : 25675 (aptitude) R 25669 25670 17863 34816 17863 4202560 12826 2207 0 0 283 4 1 0 20 0 2 0 29571874 258699264 30482 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480607416 139669595632875 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 6.26 Current children cumulated vsize (KiB) 252636 [startup+12.7002 s] /proc/loadavg: 1.15 1.09 1.05 2/57 25676 /proc/meminfo: memFree=710848/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=299292 CPUtime=12.64 /proc/25670/stat : 25670 (aptitude) S 25669 25670 17863 34816 17863 4202496 46930 2207 0 0 1240 23 1 0 20 0 2 0 29571797 306475008 42143 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274617296 139669561681483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 74823 42143 10360 1052 0 50160 0 [pid=25670/tid=25675] ppid=25669 vsize=299292 CPUtime=9.25 /proc/25670/task/25675/stat : 25675 (aptitude) R 25669 25670 17863 34816 17863 4202560 24934 2207 0 0 916 8 1 0 20 0 2 0 29571874 306475008 42143 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480606816 139669551088851 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 12.64 Current children cumulated vsize (KiB) 299292 Solver just ended. Dumping a history of the last processes samples [startup+12.8003 s] /proc/loadavg: 1.15 1.09 1.05 2/57 25676 /proc/meminfo: memFree=710848/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=299820 CPUtime=12.73 /proc/25670/stat : 25670 (aptitude) S 25669 25670 17863 34816 17863 4202496 47064 2207 0 0 1249 23 1 0 20 0 2 0 29571797 307015680 42277 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274617296 139669561681483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 74955 42277 10360 1052 0 50292 0 [pid=25670/tid=25675] ppid=25669 vsize=299820 CPUtime=9.35 /proc/25670/task/25675/stat : 25675 (aptitude) R 25669 25670 17863 34816 17863 4202560 25068 2207 0 0 926 8 1 0 20 0 2 0 29571874 307015680 42277 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480606816 139669595147357 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) 299820 [startup+16.0002 s] /proc/loadavg: 1.13 1.08 1.05 2/57 25676 /proc/meminfo: memFree=678484/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=331648 CPUtime=15.92 /proc/25670/stat : 25670 (aptitude) S 25669 25670 17863 34816 17863 4202496 55282 2207 0 0 1565 26 1 0 20 0 2 0 29571797 339607552 50234 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274617296 139669561681483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 82912 50234 10360 1052 0 58249 0 [pid=25670/tid=25675] ppid=25669 vsize=331648 CPUtime=12.53 /proc/25670/task/25675/stat : 25675 (aptitude) R 25669 25670 17863 34816 17863 4202560 33286 2207 0 0 1241 11 1 0 20 0 2 0 29571874 339607552 50234 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480605160 139669595546565 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 15.92 Current children cumulated vsize (KiB) 331648 [startup+16.8002 s] /proc/loadavg: 1.13 1.08 1.05 2/57 25676 /proc/meminfo: memFree=670424/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=337736 CPUtime=16.71 /proc/25670/stat : 25670 (aptitude) S 25669 25670 17863 34816 17863 4202496 56801 2207 0 0 1644 26 1 0 20 0 2 0 29571797 345841664 51753 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274617296 139669561681483 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 84434 51753 10361 1052 0 59771 0 [pid=25670/tid=25675] ppid=25669 vsize=337736 CPUtime=13.32 /proc/25670/task/25675/stat : 25675 (aptitude) R 25669 25670 17863 34816 17863 4202560 34805 2207 0 0 1320 11 1 0 20 0 2 0 29571874 345841664 51753 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480605208 139669550446716 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 16.71 Current children cumulated vsize (KiB) 337736 [startup+17.2002 s] /proc/loadavg: 1.13 1.08 1.05 2/57 25676 /proc/meminfo: memFree=670424/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=338196 CPUtime=17.11 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 57148 2207 0 0 1684 26 1 0 20 0 2 0 29571797 346312704 52048 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274615672 139669550427819 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 84549 52048 10409 1052 0 59879 0 [pid=25670/tid=25675] ppid=25669 vsize=338196 CPUtime=13.38 /proc/25670/task/25675/stat : 25675 (aptitude) S 25669 25670 17863 34816 17863 4202560 34925 2207 0 0 1326 11 1 0 20 0 2 0 29571874 346312704 52048 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480613888 139669561680596 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 17.11 Current children cumulated vsize (KiB) 338196 [startup+17.6002 s] /proc/loadavg: 1.13 1.08 1.05 2/57 25677 /proc/meminfo: memFree=666572/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=338196 CPUtime=17.51 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 59921 2706 0 0 1718 31 1 1 20 0 2 0 29571797 346312704 52134 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274616856 139669550446842 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 84549 52134 10410 1052 0 59879 0 [pid=25670/tid=25675] ppid=25669 vsize=338196 CPUtime=13.39 /proc/25670/task/25675/stat : 25675 (aptitude) S 25669 25670 17863 34816 17863 4202560 34925 2706 0 0 1326 11 1 1 20 0 2 0 29571874 346312704 52134 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480613888 139669561680596 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 17.51 Current children cumulated vsize (KiB) 338196 [startup+17.7032 s] /proc/loadavg: 1.13 1.08 1.05 2/57 25677 /proc/meminfo: memFree=666572/1022884 swapFree=0/0 [pid=25670] ppid=25669 vsize=338196 CPUtime=17.61 /proc/25670/stat : 25670 (aptitude) R 25669 25670 17863 34816 17863 4202496 60100 2706 0 0 1723 36 1 1 20 0 2 0 29571797 346312704 52013 18446744073709551615 139669592936448 139669597243800 140737274625536 140737274617512 139669550438802 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/25670/statm: 84549 52013 10410 1052 0 59879 0 [pid=25670/tid=25675] ppid=25669 vsize=338196 CPUtime=13.39 /proc/25670/task/25675/stat : 25675 (aptitude) S 25669 25670 17863 34816 17863 4202560 34925 2706 0 0 1326 11 1 1 20 0 2 0 29571874 346312704 52013 18446744073709551615 139669592936448 139669597243800 140737274625536 139669480613888 139669561680596 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 17.61 Current children cumulated vsize (KiB) 338196 Child status: 0 Real time (s): 17.7996 CPU time (s): 17.7131 CPU user time (s): 17.2691 CPU system time (s): 0.444027 CPU usage (%): 99.5139 Max. virtual memory (cumulated for all children) (KiB): 338196 getrusage(RUSAGE_CHILDREN,...) data: user time used= 17.2691 system time used= 0.444027 maximum resident set size= 209032 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 63319 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= 92 involuntary context switches= 349 runsolver used 0.044002 second user time and 0.044002 second system time The end