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/41.runsolver.aptitude aptitude -s -y --without-recommends install gnus mknbi libgdome2-0 libfilehandle-unget-perl libxkbsel-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

[startup+0 s]
/proc/loadavg: 1.02 1.04 0.93 2/55 21432
/proc/meminfo: memFree=820696/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=3152 CPUtime=0
/proc/21432/stat : 21432 (runsolver) R 21431 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28407196 3227648 33 18446744073709551615 134512640 134586868 4290180512 4290178560 4151206960 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.126462 s]
/proc/loadavg: 1.02 1.04 0.93 2/55 21432
/proc/meminfo: memFree=820696/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=89152 CPUtime=0.11
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 7768 1710 0 0 10 1 0 0 20 0 1 0 28407196 91291648 7567 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891884352 140542937556456 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 22288 7567 6657 1052 0 858 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 89152

[startup+0.200277 s]
/proc/loadavg: 1.02 1.04 0.93 2/55 21432
/proc/meminfo: memFree=820696/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=89152 CPUtime=0.18
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 7870 1710 0 0 17 1 0 0 20 0 1 0 28407196 91291648 7661 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891882864 140542938116499 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 22288 7661 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 89152

[startup+0.300275 s]
/proc/loadavg: 1.02 1.04 0.93 2/55 21432
/proc/meminfo: memFree=820696/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=101864 CPUtime=0.28
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 11709 1710 0 0 26 2 0 0 20 0 1 0 28407196 104308736 10755 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891882520 140542911471984 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 25466 10755 6746 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.02 1.04 0.93 2/55 21432
/proc/meminfo: memFree=820696/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=114088 CPUtime=0.68
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 13699 1710 0 0 64 4 0 0 20 0 2 0 28407196 116826112 12070 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891884360 140542944965808 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 28522 12070 6977 1052 0 7092 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 114088

[startup+1.50024 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21437
/proc/meminfo: memFree=799980/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=115500 CPUtime=1.48
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 14559 2212 0 0 141 7 0 0 20 0 2 0 28407196 118272000 12312 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891885112 140542944926810 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 28875 12312 7073 1052 0 7445 0
[pid=21432/tid=21437] ppid=21431 vsize=115500 CPUtime=0
/proc/21432/task/21437/stat : 21437 (aptitude) S 21431 21432 17863 34816 17863 4202560 6 2212 0 0 0 0 0 0 20 0 2 0 28407240 118272000 12312 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846121984 140542911460052 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) 115500

[startup+3.10024 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21438
/proc/meminfo: memFree=783860/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=206944 CPUtime=3.07
/proc/21432/stat : 21432 (aptitude) S 21431 21432 17863 34816 17863 4202496 22039 2212 0 0 298 9 0 0 20 0 2 0 28407196 211910656 19067 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891884848 140542911460939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 51736 19067 7129 1052 0 30306 0
[pid=21432/tid=21437] ppid=21431 vsize=206944 CPUtime=1.16
/proc/21432/task/21437/stat : 21437 (aptitude) R 21431 21432 17863 34816 17863 4202560 7463 2212 0 0 114 2 0 0 20 0 2 0 28407240 211910656 19067 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846113672 140542945349083 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) 206944

[startup+6.30025 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21438
/proc/meminfo: memFree=746288/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=243336 CPUtime=6.25
/proc/21432/stat : 21432 (aptitude) S 21431 21432 17863 34816 17863 4202496 31290 2212 0 0 612 13 0 0 20 0 2 0 28407196 249176064 28178 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891884848 140542911460939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 60834 28178 7129 1052 0 39404 0
[pid=21432/tid=21437] ppid=21431 vsize=243336 CPUtime=4.35
/proc/21432/task/21437/stat : 21437 (aptitude) R 21431 21432 17863 34816 17863 4202560 16714 2212 0 0 429 6 0 0 20 0 2 0 28407240 249176064 28178 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846115640 140542945593955 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) 243336

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

[startup+6.40032 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21438
/proc/meminfo: memFree=746288/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=244400 CPUtime=6.35
/proc/21432/stat : 21432 (aptitude) S 21431 21432 17863 34816 17863 4202496 31553 2212 0 0 622 13 0 0 20 0 2 0 28407196 250265600 28434 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891884848 140542911460939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 61100 28434 7129 1052 0 39670 0
[pid=21432/tid=21437] ppid=21431 vsize=244400 CPUtime=4.45
/proc/21432/task/21437/stat : 21437 (aptitude) R 21431 21432 17863 34816 17863 4202560 16977 2212 0 0 439 6 0 0 20 0 2 0 28407240 250265600 28434 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846115464 140542945413865 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 6.35
Current children cumulated vsize (KiB) 244400

[startup+7.20024 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21438
/proc/meminfo: memFree=733640/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=251272 CPUtime=7.14
/proc/21432/stat : 21432 (aptitude) S 21431 21432 17863 34816 17863 4202496 33393 2212 0 0 700 14 0 0 20 0 2 0 28407196 257302528 30144 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891884848 140542911460939 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 62818 30144 7130 1052 0 41388 0
[pid=21432/tid=21437] ppid=21431 vsize=251272 CPUtime=5.25
/proc/21432/task/21437/stat : 21437 (aptitude) R 21431 21432 17863 34816 17863 4202560 18817 2212 0 0 517 8 0 0 20 0 2 0 28407240 257302528 30144 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846113672 140542911451569 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.14
Current children cumulated vsize (KiB) 251272

[startup+7.60025 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21438
/proc/meminfo: memFree=733640/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=255392 CPUtime=7.55
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 34742 2212 0 0 740 15 0 0 20 0 2 0 28407196 261521408 31375 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891883224 140542908737511 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 63848 31375 7178 1052 0 42411 0
[pid=21432/tid=21437] ppid=21431 vsize=255392 CPUtime=5.52
/proc/21432/task/21437/stat : 21437 (aptitude) S 21431 21432 17863 34816 17863 4202560 19839 2212 0 0 544 8 0 0 20 0 2 0 28407240 261521408 31375 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846121984 140542911460052 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.55
Current children cumulated vsize (KiB) 255392

[startup+8.00024 s]
/proc/loadavg: 1.02 1.04 0.93 2/57 21438
/proc/meminfo: memFree=722852/1022884 swapFree=0/0
[pid=21432] ppid=21431 vsize=255460 CPUtime=7.95
/proc/21432/stat : 21432 (aptitude) R 21431 21432 17863 34816 17863 4202496 36742 2712 0 0 776 18 0 1 20 0 2 0 28407196 261591040 31381 18446744073709551615 140542942715904 140542947023256 140734891893088 140734891885352 140542944449402 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21432/statm: 63865 31381 7179 1052 0 42428 0
[pid=21432/tid=21437] ppid=21431 vsize=255460 CPUtime=5.53
/proc/21432/task/21437/stat : 21437 (aptitude) S 21431 21432 17863 34816 17863 4202560 19839 2712 0 0 544 8 0 1 20 0 2 0 28407240 261591040 31381 18446744073709551615 140542942715904 140542947023256 140734891893088 140542846121984 140542911460052 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 7.95
Current children cumulated vsize (KiB) 255460

Child status: 0
Real time (s): 8.04095
CPU time (s): 8.0125
CPU user time (s): 7.78049
CPU system time (s): 0.232014
CPU usage (%): 99.6462
Max. virtual memory (cumulated for all children) (KiB): 255460

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 7.78049
system time used= 0.232014
maximum resident set size= 125932
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 40155
page faults= 0
swaps= 0
block input operations= 0
block output operations= 112
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 75
involuntary context switches= 188

runsolver used 0.012 second user time and 0.028001 second system time

The end