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/135.runsolver.aptitude aptitude -s -y --without-recommends remove libxrender1 libgnomecups1.0-1 gnome-system-tools xlibmesa-dri kpercentage 

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.01 1.00 2/55 22453
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=3152 CPUtime=0
/proc/22453/stat : 22453 (runsolver) R 22452 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28695186 3227648 33 18446744073709551615 134512640 134586868 4291896496 4291894544 4151985200 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.148254 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22453
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=89152 CPUtime=0.13
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 7773 1708 0 0 11 2 0 0 20 0 1 0 28695186 91291648 7573 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475703728 140607201392104 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 22288 7573 6662 1052 0 858 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 89152

[startup+0.200282 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22453
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=89152 CPUtime=0.18
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 7870 1708 0 0 16 2 0 0 20 0 1 0 28695186 91291648 7662 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475702240 140607201400471 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 22288 7662 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.300271 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22453
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=101864 CPUtime=0.29
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 11709 1708 0 0 26 3 0 0 20 0 1 0 28695186 104308736 10756 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475701896 140607209477520 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.29
Current children cumulated vsize (KiB) 101864

[startup+0.7002 s]
/proc/loadavg: 1.00 1.01 1.00 2/55 22453
/proc/meminfo: memFree=904100/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=113880 CPUtime=0.68
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 13635 1708 0 0 64 4 0 0 20 0 2 0 28695186 116613120 12006 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475703736 140607209121384 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 28470 12006 6961 1052 0 7040 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 113880

[startup+1.50024 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22458
/proc/meminfo: memFree=883632/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=115336 CPUtime=1.47
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 13860 1708 0 0 143 4 0 0 20 0 2 0 28695186 118104064 12229 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475699168 140607164062073 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 28834 12229 7033 1052 0 7404 0
[pid=22453/tid=22458] ppid=22452 vsize=115336 CPUtime=0
/proc/22453/task/22458/stat : 22458 (aptitude) S 22452 22453 17863 34816 17863 4202560 4 1708 0 0 0 0 0 0 20 0 2 0 28695230 118104064 12229 18446744073709551615 140607206551552 140607210858904 140736475712464 140607109957632 140607175295700 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) 115336

[startup+3.1003 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22458
/proc/meminfo: memFree=865528/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=158336 CPUtime=3.07
/proc/22453/stat : 22453 (aptitude) S 22452 22453 17863 34816 17863 4202496 24880 1708 0 0 300 7 0 0 20 0 2 0 28695186 162136064 23248 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475704224 140607175296587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 39584 23248 7088 1052 0 18154 0
[pid=22453/tid=22458] ppid=22452 vsize=158336 CPUtime=1.34
/proc/22453/task/22458/stat : 22458 (aptitude) R 22452 22453 17863 34816 17863 4202560 11019 1708 0 0 132 2 0 0 20 0 2 0 28695230 162136064 23248 18446744073709551615 140607206551552 140607210858904 140736475712464 140607109951160 140607209227801 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) 158336

Solver just ended. Dumping a history of the last processes samples

[startup+3.20031 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22458
/proc/meminfo: memFree=865528/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=160316 CPUtime=3.17
/proc/22453/stat : 22453 (aptitude) S 22452 22453 17863 34816 17863 4202496 25395 1708 0 0 310 7 0 0 20 0 2 0 28695186 164163584 23763 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475704224 140607175296587 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 40079 23763 7088 1052 0 18649 0
[pid=22453/tid=22458] ppid=22452 vsize=160316 CPUtime=1.44
/proc/22453/task/22458/stat : 22458 (aptitude) R 22452 22453 17863 34816 17863 4202560 11534 1708 0 0 142 2 0 0 20 0 2 0 28695230 164163584 23763 18446744073709551615 140607206551552 140607210858904 140736475712464 140607109951112 140607209259777 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.17
Current children cumulated vsize (KiB) 160316

[startup+4.00025 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22458
/proc/meminfo: memFree=835024/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=173720 CPUtime=3.97
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 28795 1708 0 0 389 8 0 0 20 0 2 0 28695186 177889280 27161 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475702552 140607164042864 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 43430 27161 7140 1052 0 21993 0
[pid=22453/tid=22458] ppid=22452 vsize=173720 CPUtime=2.12
/proc/22453/task/22458/stat : 22458 (aptitude) S 22452 22453 17863 34816 17863 4202560 14712 1708 0 0 209 3 0 0 20 0 2 0 28695230 177889280 27161 18446744073709551615 140607206551552 140607210858904 140736475712464 140607109957632 140607175295700 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.97
Current children cumulated vsize (KiB) 173720

[startup+4.2003 s]
/proc/loadavg: 1.00 1.01 1.00 2/57 22458
/proc/meminfo: memFree=835024/1022884 swapFree=0/0
[pid=22453] ppid=22452 vsize=152052 CPUtime=4.16
/proc/22453/stat : 22453 (aptitude) R 22452 22453 17863 34816 17863 4202496 28795 1708 0 0 408 8 0 0 20 0 2 0 28695186 155701248 21766 18446744073709551615 140607206551552 140607210858904 140736475712464 140736475704680 140607208758716 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/22453/statm: 38013 21766 7140 1052 0 16576 0
[pid=22453/tid=22458] ppid=22452 vsize=152052 CPUtime=2.12
/proc/22453/task/22458/stat : 22458 (aptitude) S 22452 22453 17863 34816 17863 4202560 14712 1708 0 0 209 3 0 0 20 0 2 0 28695230 155701248 21766 18446744073709551615 140607206551552 140607210858904 140736475712464 140607109957632 140607175295700 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 4.16
Current children cumulated vsize (KiB) 152052

Child status: 0
Real time (s): 4.28239
CPU time (s): 4.26827
CPU user time (s): 4.16026
CPU system time (s): 0.108006
CPU usage (%): 99.6702
Max. virtual memory (cumulated for all children) (KiB): 173720

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 4.16026
system time used= 0.108006
maximum resident set size= 108644
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30579
page faults= 0
swaps= 0
block input operations= 0
block output operations= 80
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 62
involuntary context switches= 120

runsolver used 0 second user time and 0.024001 second system time

The end