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/74.runsolver.aptitude aptitude -s -y --without-recommends install libhttp-ocaml-dev librsvg2-ruby libsvga1-dev regexplorer librlog1 

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.07 1.06 0.99 2/55 21739
/proc/meminfo: memFree=908704/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=3152 CPUtime=0
/proc/21739/stat : 21739 (runsolver) R 21738 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28549051 3227648 33 18446744073709551615 134512640 134586868 4286808768 4286806816 4152222768 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 788 33 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.170691 s]
/proc/loadavg: 1.07 1.06 0.99 2/55 21739
/proc/meminfo: memFree=908704/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=89152 CPUtime=0.16
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 7776 1707 0 0 14 2 0 0 20 0 1 0 28549051 91291648 7576 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428128 139675917621536 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 22288 7576 6664 1052 0 858 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 89152

[startup+0.200289 s]
/proc/loadavg: 1.07 1.06 0.99 2/55 21739
/proc/meminfo: memFree=908704/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=89152 CPUtime=0.19
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 7871 1707 0 0 17 2 0 0 20 0 1 0 28549051 91291648 7663 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757426640 139675917633506 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 22288 7663 6726 1052 0 858 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 89152

[startup+0.300274 s]
/proc/loadavg: 1.07 1.06 0.99 2/55 21739
/proc/meminfo: memFree=908704/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=101864 CPUtime=0.28
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 11709 1707 0 0 25 3 0 0 20 0 1 0 28549051 104308736 10756 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757426296 139675880320535 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 25466 10756 6745 1052 0 4036 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 101864

[startup+0.700205 s]
/proc/loadavg: 1.07 1.06 0.99 2/55 21739
/proc/meminfo: memFree=908704/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=110236 CPUtime=0.68
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 12683 1707 0 0 63 5 0 0 20 0 2 0 28549051 112881664 11055 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428904 139675880290775 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 27559 11055 6961 1052 0 6129 0
Current children cumulated CPU time (s) 0.68
Current children cumulated vsize (KiB) 110236

[startup+1.50031 s]
/proc/loadavg: 1.07 1.06 0.99 2/57 21744
/proc/meminfo: memFree=887740/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=115412 CPUtime=1.47
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 14565 2205 0 0 140 7 0 0 20 0 2 0 28549051 118181888 12365 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428888 139675880290440 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 28853 12365 7073 1052 0 7423 0
[pid=21739/tid=21744] ppid=21738 vsize=115412 CPUtime=0
/proc/21739/task/21744/stat : 21744 (aptitude) S 21738 21739 17863 34816 17863 4202560 6 2205 0 0 0 0 0 0 20 0 2 0 28549096 118181888 12365 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826186240 139675891524308 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) 115412

[startup+3.10025 s]
/proc/loadavg: 1.07 1.06 0.99 2/57 21745
/proc/meminfo: memFree=881292/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=200356 CPUtime=3.06
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 20355 2205 0 0 298 8 0 0 20 0 2 0 28549051 205164544 17430 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 50089 17430 7130 1052 0 28659 0
[pid=21739/tid=21744] ppid=21738 vsize=200356 CPUtime=1.04
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 5711 2205 0 0 103 1 0 0 20 0 2 0 28549096 205164544 17430 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826177560 139675918179889 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) 200356

[startup+6.30024 s]
/proc/loadavg: 1.06 1.05 0.99 2/57 21745
/proc/meminfo: memFree=837768/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=238656 CPUtime=6.26
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 29959 2205 0 0 614 12 0 0 20 0 2 0 28549051 244383744 26988 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 59664 26988 7130 1052 0 38234 0
[pid=21739/tid=21744] ppid=21738 vsize=238656 CPUtime=4.22
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 15315 2205 0 0 418 4 0 0 20 0 2 0 28549096 244383744 26988 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826177560 139675880280373 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) 238656

[startup+12.7002 s]
/proc/loadavg: 1.06 1.05 0.99 2/57 21745
/proc/meminfo: memFree=765972/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=305580 CPUtime=12.62
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 46712 2205 0 0 1244 18 0 0 20 0 2 0 28549051 312913920 43718 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 76395 43718 7130 1052 0 54965 0
[pid=21739/tid=21744] ppid=21738 vsize=305580 CPUtime=10.59
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 32068 2205 0 0 1049 10 0 0 20 0 2 0 28549096 312913920 43718 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826177560 139675880271451 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) 305580

[startup+25.5003 s]
/proc/loadavg: 1.04 1.05 0.99 2/57 21745
/proc/meminfo: memFree=690952/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=377360 CPUtime=25.36
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 64842 2205 0 0 2511 25 0 0 20 0 2 0 28549051 386416640 61653 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 94340 61653 7130 1052 0 72910 0
[pid=21739/tid=21744] ppid=21738 vsize=377360 CPUtime=23.33
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 50198 2205 0 0 2316 17 0 0 20 0 2 0 28549096 386416640 61653 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826177560 139675925413339 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) 377360

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

[startup+25.6003 s]
/proc/loadavg: 1.04 1.05 0.99 2/57 21745
/proc/meminfo: memFree=690952/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=377888 CPUtime=25.46
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 64963 2205 0 0 2521 25 0 0 20 0 2 0 28549051 386957312 61774 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 94472 61774 7130 1052 0 73042 0
[pid=21739/tid=21744] ppid=21738 vsize=377888 CPUtime=23.43
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 50319 2205 0 0 2326 17 0 0 20 0 2 0 28549096 386957312 61774 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826179768 139675925554416 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) 377888

[startup+38.4002 s]
/proc/loadavg: 1.04 1.05 0.99 2/57 21745
/proc/meminfo: memFree=634284/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=436840 CPUtime=38.2
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 79750 2205 0 0 3788 32 0 0 20 0 2 0 28549051 447324160 76523 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 109210 76523 7144 1052 0 87780 0
[pid=21739/tid=21744] ppid=21738 vsize=436840 CPUtime=36.18
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 65099 2205 0 0 3593 25 0 0 20 0 2 0 28549096 447324160 76523 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826177560 139675889089515 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) 436840

[startup+44.8002 s]
/proc/loadavg: 1.03 1.05 0.99 2/57 21745
/proc/meminfo: memFree=606632/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=463944 CPUtime=44.58
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 86462 2205 0 0 4423 35 0 0 20 0 2 0 28549051 475078656 83234 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 115986 83234 7144 1052 0 94556 0
[pid=21739/tid=21744] ppid=21738 vsize=463944 CPUtime=42.55
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 71811 2205 0 0 4227 28 0 0 20 0 2 0 28549096 475078656 83234 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826177560 139675925413082 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) 463944

[startup+48.0002 s]
/proc/loadavg: 1.03 1.05 0.99 2/57 21745
/proc/meminfo: memFree=591876/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=478392 CPUtime=47.76
/proc/21739/stat : 21739 (aptitude) S 21738 21739 17863 34816 17863 4202496 90099 2205 0 0 4740 36 0 0 20 0 2 0 28549051 489873408 86871 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757428624 139675891525195 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 119598 86871 7144 1052 0 98168 0
[pid=21739/tid=21744] ppid=21738 vsize=478392 CPUtime=45.72
/proc/21739/task/21744/stat : 21744 (aptitude) R 21738 21739 17863 34816 17863 4202560 75448 2205 0 0 4544 28 0 0 20 0 2 0 28549096 489873408 86871 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826179720 139675925515911 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.76
Current children cumulated vsize (KiB) 478392

[startup+49.6032 s]
/proc/loadavg: 1.03 1.05 0.99 2/57 21745
/proc/meminfo: memFree=581088/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=484908 CPUtime=49.36
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 92072 2205 0 0 4898 38 0 0 20 0 2 0 28549051 496545792 88713 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757427000 139675925382432 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 121227 88713 7191 1052 0 99790 0
[pid=21739/tid=21744] ppid=21738 vsize=484908 CPUtime=47.07
/proc/21739/task/21744/stat : 21744 (aptitude) S 21738 21739 17863 34816 17863 4202560 77078 2205 0 0 4677 30 0 0 20 0 2 0 28549096 496545792 88713 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826186240 139675891524308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 49.36
Current children cumulated vsize (KiB) 484908

[startup+50.4002 s]
/proc/loadavg: 1.03 1.05 0.99 2/57 21745
/proc/meminfo: memFree=581088/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=484984 CPUtime=50.15
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 94031 2205 0 0 4977 38 0 0 20 0 2 0 28549051 496623616 88652 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757429064 139675924986535 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 121246 88652 7192 1052 0 99809 0
[pid=21739/tid=21744] ppid=21738 vsize=484984 CPUtime=47.07
/proc/21739/task/21744/stat : 21744 (aptitude) S 21738 21739 17863 34816 17863 4202560 77078 2205 0 0 4677 30 0 0 20 0 2 0 28549096 496623616 88652 18446744073709551615 139675922780160 139675927087512 140734757436864 139675826186240 139675891524308 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 50.15
Current children cumulated vsize (KiB) 484984

[startup+50.6011 s]
/proc/loadavg: 1.03 1.05 0.99 2/56 21746
/proc/meminfo: memFree=718976/1022884 swapFree=0/0
[pid=21739] ppid=21738 vsize=396036 CPUtime=50.37
/proc/21739/stat : 21739 (aptitude) R 21738 21739 17863 34816 17863 4202496 94821 2704 0 0 4985 50 0 2 20 0 1 0 28549051 405540864 54224 18446744073709551615 139675922780160 139675927087512 140734757436864 140734757433848 139675880646122 0 134217728 4096 0 0 0 0 17 0 0 0 0 0 0
/proc/21739/statm: 99009 54224 7195 1052 0 77572 0
Current children cumulated CPU time (s) 50.37
Current children cumulated vsize (KiB) 396036

Child status: 0
Real time (s): 50.6578
CPU time (s): 50.4312
CPU user time (s): 49.8591
CPU system time (s): 0.572035
CPU usage (%): 99.5527
Max. virtual memory (cumulated for all children) (KiB): 484984

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 49.8591
system time used= 0.572035
maximum resident set size= 355332
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 97627
page faults= 0
swaps= 0
block input operations= 0
block output operations= 152
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 160
involuntary context switches= 898

runsolver used 0.100006 second user time and 0.136008 second system time

The end