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/logs/84.runsolver.aptitude aptitude -s -y --without-recommends install libcrypt-gpg-perl gtoaster cl-ptester libapache-mod-python2.3 opensc 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.05 1.09 1.02 2/55 22052 /proc/meminfo: memFree=850220/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=3152 CPUtime=0 /proc/22052/stat : 22052 (runsolver) R 22051 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28591460 3227648 32 18446744073709551615 134512640 134586868 4287361680 4287359728 4151612464 0 0 0 24578 0 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 788 32 0 19 0 73 0 Current StackSize limit: 8192 KiB [startup+0.16898 s] /proc/loadavg: 1.05 1.09 1.02 2/55 22052 /proc/meminfo: memFree=850220/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=89152 CPUtime=0.15 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 7775 1708 0 0 13 2 0 0 20 0 1 0 28591460 91291648 7575 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302000928 140637043439152 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 22288 7575 6664 1052 0 858 0 Current children cumulated CPU time (s) 0.15 Current children cumulated vsize (KiB) 89152 [startup+0.200288 s] /proc/loadavg: 1.05 1.09 1.02 2/55 22052 /proc/meminfo: memFree=850220/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=89152 CPUtime=0.18 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 7870 1708 0 0 16 2 0 0 20 0 1 0 28591460 91291648 7662 18446744073709551615 140637042610176 140637046917528 140734302009664 140734301999440 140637037463522 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 22288 7662 6726 1052 0 858 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 89152 [startup+0.300273 s] /proc/loadavg: 1.05 1.09 1.02 2/55 22052 /proc/meminfo: memFree=850220/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=101864 CPUtime=0.28 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 11705 1708 0 0 26 2 0 0 20 0 1 0 28591460 104308736 10752 18446744073709551615 140637042610176 140637046917528 140734302009664 140734301999032 140637045535459 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 25466 10752 6742 1052 0 4036 0 Current children cumulated CPU time (s) 0.28 Current children cumulated vsize (KiB) 101864 [startup+0.700208 s] /proc/loadavg: 1.05 1.09 1.02 2/55 22052 /proc/meminfo: memFree=850220/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=114144 CPUtime=0.68 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 13714 1708 0 0 65 3 0 0 20 0 2 0 28591460 116883456 12085 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302000936 140637008543341 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 28536 12085 6977 1052 0 7106 0 Current children cumulated CPU time (s) 0.68 Current children cumulated vsize (KiB) 114144 [startup+1.50025 s] /proc/loadavg: 1.05 1.09 1.02 2/57 22057 /proc/meminfo: memFree=829504/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=115568 CPUtime=1.47 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 14607 2211 0 0 143 4 0 0 20 0 2 0 28591460 118341632 12329 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001688 140637000120396 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 28892 12329 7073 1052 0 7462 0 [pid=22052/tid=22057] ppid=22051 vsize=115568 CPUtime=0 /proc/22052/task/22057/stat : 22057 (aptitude) S 22051 22052 17863 34816 17863 4202560 6 2211 0 0 0 0 0 0 20 0 2 0 28591505 118341632 12329 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946016256 140637011354324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.47 Current children cumulated vsize (KiB) 115568 [startup+3.10024 s] /proc/loadavg: 1.05 1.09 1.02 2/57 22058 /proc/meminfo: memFree=820824/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=206848 CPUtime=3.06 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 21961 2211 0 0 298 8 0 0 20 0 2 0 28591460 211812352 19056 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 51712 19056 7130 1052 0 30282 0 [pid=22052/tid=22057] ppid=22051 vsize=206848 CPUtime=1.16 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 7338 2211 0 0 112 4 0 0 20 0 2 0 28591505 211812352 19056 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946009944 140637000113716 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 3.06 Current children cumulated vsize (KiB) 206848 [startup+6.30025 s] /proc/loadavg: 1.04 1.09 1.02 2/57 22058 /proc/meminfo: memFree=766884/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=248232 CPUtime=6.25 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 32398 2211 0 0 610 15 0 0 20 0 2 0 28591460 254189568 29400 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 62058 29400 7130 1052 0 40628 0 [pid=22052/tid=22057] ppid=22051 vsize=248232 CPUtime=4.33 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 17775 2211 0 0 423 10 0 0 20 0 2 0 28591505 254189568 29400 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946007576 140637045385445 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) 248232 [startup+12.7002 s] /proc/loadavg: 1.04 1.08 1.02 2/57 22058 /proc/meminfo: memFree=721376/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=291256 CPUtime=12.62 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 43164 2211 0 0 1241 21 0 0 20 0 2 0 28591460 298246144 40143 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 72814 40143 7130 1052 0 51384 0 [pid=22052/tid=22057] ppid=22051 vsize=291256 CPUtime=10.7 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 28541 2211 0 0 1054 16 0 0 20 0 2 0 28591505 298246144 40143 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946007576 140637000120416 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) 291256 [startup+25.5003 s] /proc/loadavg: 1.03 1.08 1.02 2/57 22058 /proc/meminfo: memFree=637056/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=372820 CPUtime=25.36 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 63578 2211 0 0 2503 33 0 0 20 0 2 0 28591460 381767680 60512 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 93205 60512 7130 1052 0 71775 0 [pid=22052/tid=22057] ppid=22051 vsize=372820 CPUtime=23.44 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 48955 2211 0 0 2316 28 0 0 20 0 2 0 28591505 381767680 60512 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946009864 140637043199184 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.36 Current children cumulated vsize (KiB) 372820 Solver just ended. Dumping a history of the last processes samples [startup+25.6003 s] /proc/loadavg: 1.03 1.08 1.02 2/57 22058 /proc/meminfo: memFree=637056/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=373348 CPUtime=25.46 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 63695 2211 0 0 2513 33 0 0 20 0 2 0 28591460 382308352 60629 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 93337 60629 7130 1052 0 71907 0 [pid=22052/tid=22057] ppid=22051 vsize=373348 CPUtime=23.54 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 49072 2211 0 0 2326 28 0 0 20 0 2 0 28591505 382308352 60629 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946007576 140637045370496 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 373348 [startup+38.4002 s] /proc/loadavg: 1.02 1.08 1.02 2/57 22058 /proc/meminfo: memFree=577164/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=435980 CPUtime=38.2 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 79582 2211 0 0 3779 41 0 0 20 0 2 0 28591460 446443520 76318 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 108995 76318 7144 1052 0 87565 0 [pid=22052/tid=22057] ppid=22051 vsize=435980 CPUtime=36.28 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 64952 2211 0 0 3592 36 0 0 20 0 2 0 28591505 446443520 76318 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946009912 140637045256568 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 38.2 Current children cumulated vsize (KiB) 435980 [startup+44.8002 s] /proc/loadavg: 1.02 1.08 1.02 2/57 22058 /proc/meminfo: memFree=540336/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=475088 CPUtime=44.58 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 89433 2211 0 0 4413 45 0 0 20 0 2 0 28591460 486490112 86113 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 118772 86113 7145 1052 0 97342 0 [pid=22052/tid=22057] ppid=22051 vsize=475088 CPUtime=42.65 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 74803 2211 0 0 4225 40 0 0 20 0 2 0 28591505 486490112 86113 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946007528 140637000112069 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 44.58 Current children cumulated vsize (KiB) 475088 [startup+46.4003 s] /proc/loadavg: 1.02 1.07 1.02 2/57 22058 /proc/meminfo: memFree=522976/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=487272 CPUtime=46.16 /proc/22052/stat : 22052 (aptitude) S 22051 22052 17863 34816 17863 4202496 92390 2211 0 0 4571 45 0 0 20 0 2 0 28591460 498966528 89070 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302001424 140637011355211 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 121818 89070 7145 1052 0 100388 0 [pid=22052/tid=22057] ppid=22051 vsize=487272 CPUtime=44.24 /proc/22052/task/22057/stat : 22057 (aptitude) R 22051 22052 17863 34816 17863 4202560 77760 2211 0 0 4384 40 0 0 20 0 2 0 28591505 498966528 89070 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946009688 140637045317862 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 46.16 Current children cumulated vsize (KiB) 487272 [startup+48.0003 s] /proc/loadavg: 1.02 1.07 1.02 2/57 22058 /proc/meminfo: memFree=514544/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=495308 CPUtime=47.75 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 94543 2211 0 0 4729 46 0 0 20 0 2 0 28591460 507195392 91194 18446744073709551615 140637042610176 140637046917528 140734302009664 140734301999800 140637000101547 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 123827 91194 7192 1052 0 102390 0 [pid=22052/tid=22057] ppid=22051 vsize=495308 CPUtime=45.23 /proc/22052/task/22057/stat : 22057 (aptitude) S 22051 22052 17863 34816 17863 4202560 79735 2211 0 0 4481 42 0 0 20 0 2 0 28591505 507195392 91194 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946016256 140637011354324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 47.75 Current children cumulated vsize (KiB) 495308 [startup+48.4002 s] /proc/loadavg: 1.02 1.07 1.02 2/57 22058 /proc/meminfo: memFree=513180/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=495308 CPUtime=48.16 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 96354 2211 0 0 4769 47 0 0 20 0 2 0 28591460 507195392 91196 18446744073709551615 140637042610176 140637046917528 140734302009664 140734301997528 140637044816771 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 123827 91196 7194 1052 0 102390 0 [pid=22052/tid=22057] ppid=22051 vsize=495308 CPUtime=45.23 /proc/22052/task/22057/stat : 22057 (aptitude) S 22051 22052 17863 34816 17863 4202560 79735 2211 0 0 4481 42 0 0 20 0 2 0 28591505 507195392 91196 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946016256 140637011354324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 48.16 Current children cumulated vsize (KiB) 495308 [startup+48.6007 s] /proc/loadavg: 1.02 1.07 1.02 2/57 22058 /proc/meminfo: memFree=513180/1022884 swapFree=0/0 [pid=22052] ppid=22051 vsize=495308 CPUtime=48.37 /proc/22052/stat : 22052 (aptitude) R 22051 22052 17863 34816 17863 4202496 96640 2712 0 0 4776 59 0 2 20 0 2 0 28591460 507195392 54315 18446744073709551615 140637042610176 140637046917528 140734302009664 140734302005928 140637000476138 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0 /proc/22052/statm: 123827 54315 7194 1052 0 102390 0 [pid=22052/tid=22057] ppid=22051 vsize=495308 CPUtime=45.25 /proc/22052/task/22057/stat : 22057 (aptitude) S 22051 22052 17863 34816 17863 4202560 79735 2712 0 0 4481 42 0 2 20 0 2 0 28591505 507195392 54315 18446744073709551615 140637042610176 140637046917528 140734302009664 140636946016256 140637011354324 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0 Current children cumulated CPU time (s) 48.37 Current children cumulated vsize (KiB) 495308 Child status: 0 Real time (s): 48.6566 CPU time (s): 48.439 CPU user time (s): 47.771 CPU system time (s): 0.668041 CPU usage (%): 99.5528 Max. virtual memory (cumulated for all children) (KiB): 495308 getrusage(RUSAGE_CHILDREN,...) data: user time used= 47.771 system time used= 0.668041 maximum resident set size= 364976 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 99497 page faults= 0 swaps= 0 block input operations= 0 block output operations= 56 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 155 involuntary context switches= 874 runsolver used 0.044002 second user time and 0.184011 second system time The end