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/82.runsolver.aptitude aptitude -s -y --without-recommends install libant1.5-java dpsyco-ssh coco-java netwag mp3splt 

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.44 1.14 1.03 2/55 22034
/proc/meminfo: memFree=935160/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=3152 CPUtime=0
/proc/22034/stat : 22034 (runsolver) R 22033 17863 17863 34816 17863 4202560 0 0 0 0 0 0 0 0 20 0 1 0 28578819 3227648 32 18446744073709551615 134512640 134586868 4291288176 4291286224 4151374896 0 0 0 24578 0 0 0 17 0 0 0 0 0 0
/proc/22034/statm: 788 32 0 19 0 73 0
Current StackSize limit: 8192 KiB


[startup+0.192751 s]
/proc/loadavg: 1.44 1.14 1.03 2/55 22034
/proc/meminfo: memFree=935160/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=25980 CPUtime=0
/proc/22034/stat : 22034 (aptitude) D 22033 22034 17863 34816 17863 4202496 149 0 16 0 0 0 0 0 20 0 1 0 28578819 26603520 77 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921553176 139886038737367 0 0 0 0 0 0 0 17 0 0 0 18 0 0
/proc/22034/statm: 6495 77 50 1052 0 32 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 25980

[startup+0.200373 s]
/proc/loadavg: 1.44 1.14 1.03 2/55 22034
/proc/meminfo: memFree=935160/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=28716 CPUtime=0
/proc/22034/stat : 22034 (aptitude) D 22033 22034 17863 34816 17863 4202496 150 0 16 0 0 0 0 0 20 0 1 0 28578819 29405184 78 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921552584 139886038742563 0 0 0 0 0 0 0 17 0 0 0 19 0 0
/proc/22034/statm: 7179 78 50 1052 0 33 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 28716

[startup+0.300351 s]
/proc/loadavg: 1.44 1.14 1.03 2/55 22034
/proc/meminfo: memFree=935160/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=44448 CPUtime=0
/proc/22034/stat : 22034 (aptitude) D 22033 22034 17863 34816 17863 4202496 172 0 25 0 0 0 0 0 20 0 1 0 28578819 45514752 105 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921552152 139886038742406 0 0 0 0 0 0 0 17 0 0 0 29 0 0
/proc/22034/statm: 11112 105 65 1052 0 61 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 44448

[startup+0.700273 s]
/proc/loadavg: 1.44 1.14 1.03 2/55 22034
/proc/meminfo: memFree=935160/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=54972 CPUtime=0
/proc/22034/stat : 22034 (aptitude) D 22033 22034 17863 34816 17863 4202496 1072 0 68 0 0 0 0 0 20 0 1 0 28578819 56291328 1030 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921551816 139885998728944 0 134217728 4096 0 0 0 0 17 0 0 0 67 0 0
/proc/22034/statm: 13743 1030 859 1052 0 107 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 54972

[startup+1.50031 s]
/proc/loadavg: 1.40 1.14 1.03 1/56 22038
/proc/meminfo: memFree=920772/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=89152 CPUtime=0.03
/proc/22034/stat : 22034 (aptitude) D 22033 22034 17863 34816 17863 4202496 2225 1704 168 4 1 2 0 0 20 0 1 0 28578819 91291648 2193 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547440 139886035933016 0 134217728 4096 0 0 0 0 17 0 0 0 140 0 0
/proc/22034/statm: 22288 2193 1282 1052 0 858 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 89152

[startup+3.10021 s]
/proc/loadavg: 1.40 1.14 1.03 1/56 22038
/proc/meminfo: memFree=907628/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=101864 CPUtime=0.37
/proc/22034/stat : 22034 (aptitude) D 22033 22034 17863 34816 17863 4202496 11370 1704 339 4 32 5 0 0 20 0 1 0 28578819 104308736 10756 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921545400 139886009639280 0 134217728 4096 0 0 0 0 17 0 0 0 265 0 0
/proc/22034/statm: 25466 10756 6746 1052 0 4036 0
Current children cumulated CPU time (s) 0.37
Current children cumulated vsize (KiB) 101864
heavy processes:

[startup+6.30024 s]
/proc/loadavg: 1.37 1.14 1.03 2/57 22040
/proc/meminfo: memFree=817472/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=140128 CPUtime=3.27
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 21382 2201 350 5 314 12 1 0 20 0 2 0 28578819 143491072 18762 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 35032 18762 7129 1052 0 13602 0
[pid=22034/tid=22039] ppid=22033 vsize=140128 CPUtime=1.17
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 7063 2201 0 5 114 2 1 0 20 0 2 0 28579160 143491072 18762 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944280600 139886043643137 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 3.27
Current children cumulated vsize (KiB) 140128
heavy processes:

[startup+12.7002 s]
/proc/loadavg: 1.34 1.14 1.03 2/57 22040
/proc/meminfo: memFree=746296/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=267788 CPUtime=9.63
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 36972 2201 350 5 944 18 1 0 20 0 2 0 28578819 274214912 34256 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 66947 34256 7129 1052 0 45517 0
[pid=22034/tid=22039] ppid=22033 vsize=267788 CPUtime=7.53
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 22652 2201 0 5 744 8 1 0 20 0 2 0 28579160 274214912 34256 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944280600 139886043516379 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 9.63
Current children cumulated vsize (KiB) 267788
heavy processes:

[startup+25.5003 s]
/proc/loadavg: 1.29 1.13 1.03 2/57 22040
/proc/meminfo: memFree=635564/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=375276 CPUtime=22.37
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 63839 2201 350 5 2204 32 1 0 20 0 2 0 28578819 384282624 61106 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 93819 61106 7129 1052 0 72389 0
[pid=22034/tid=22039] ppid=22033 vsize=375276 CPUtime=20.27
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 49519 2201 0 5 2004 22 1 0 20 0 2 0 28579160 384282624 61106 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944280680 139885998383384 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 22.37
Current children cumulated vsize (KiB) 375276

[startup+51.1003 s]
/proc/loadavg: 1.17 1.12 1.03 2/57 22040
/proc/meminfo: memFree=507968/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=503740 CPUtime=47.85
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 96052 2201 350 5 4733 51 1 0 20 0 2 0 28578819 515829760 93184 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 125935 93184 7143 1052 0 104505 0
[pid=22034/tid=22039] ppid=22033 vsize=503740 CPUtime=45.75
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 81725 2201 0 5 4533 41 1 0 20 0 2 0 28579160 515829760 93184 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944282808 139885998393440 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 47.85
Current children cumulated vsize (KiB) 503740

[startup+102.3 s]
/proc/loadavg: 1.07 1.10 1.02 2/57 22040
/proc/meminfo: memFree=295804/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=713544 CPUtime=98.82
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 148428 2201 350 5 9797 84 1 0 20 0 2 0 28578819 730669056 145531 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 178386 145531 7143 1052 0 156956 0
[pid=22034/tid=22039] ppid=22033 vsize=713544 CPUtime=96.72
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 134101 2201 0 5 9596 75 1 0 20 0 2 0 28579160 730669056 145531 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944280680 139886041528626 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 98.82
Current children cumulated vsize (KiB) 713544

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

[startup+102.403 s]
/proc/loadavg: 1.07 1.10 1.02 2/57 22040
/proc/meminfo: memFree=295804/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=713808 CPUtime=98.92
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 148514 2201 350 5 9807 84 1 0 20 0 2 0 28578819 730939392 145617 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 178452 145617 7143 1052 0 157022 0
[pid=22034/tid=22039] ppid=22033 vsize=713808 CPUtime=96.82
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 134187 2201 0 5 9606 75 1 0 20 0 2 0 28579160 730939392 145617 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944280728 139885998383376 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 98.92
Current children cumulated vsize (KiB) 713808

[startup+108.8 s]
/proc/loadavg: 1.07 1.10 1.02 2/57 22040
/proc/meminfo: memFree=276088/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=736652 CPUtime=105.3
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 154232 2201 350 5 10442 87 1 0 20 0 2 0 28578819 754331648 151333 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 184163 151333 7143 1052 0 162733 0
[pid=22034/tid=22039] ppid=22033 vsize=736652 CPUtime=103.19
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 139905 2201 0 5 10241 77 1 0 20 0 2 0 28579160 754331648 151333 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944282936 139885998393584 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 105.3
Current children cumulated vsize (KiB) 736652

[startup+112 s]
/proc/loadavg: 1.06 1.09 1.02 2/57 22040
/proc/meminfo: memFree=263564/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=749064 CPUtime=108.48
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 157324 2201 350 5 10758 89 1 0 20 0 2 0 28578819 767041536 154425 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 187266 154425 7143 1052 0 165836 0
[pid=22034/tid=22039] ppid=22033 vsize=749064 CPUtime=106.38
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 142997 2201 0 5 10557 80 1 0 20 0 2 0 28579160 767041536 154425 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944282888 139886043529974 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 108.48
Current children cumulated vsize (KiB) 749064

[startup+113.6 s]
/proc/loadavg: 1.06 1.09 1.02 2/57 22040
/proc/meminfo: memFree=254760/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=755800 CPUtime=110.07
/proc/22034/stat : 22034 (aptitude) S 22033 22034 17863 34816 17863 4202496 159014 2201 350 5 10916 90 1 0 20 0 2 0 28578819 773939200 156115 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547728 139886009628235 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 296 0 0
/proc/22034/statm: 188950 156115 7144 1052 0 167520 0
[pid=22034/tid=22039] ppid=22033 vsize=755800 CPUtime=107.96
/proc/22034/task/22039/stat : 22039 (aptitude) R 22033 22034 17863 34816 17863 4202560 144687 2201 0 5 10715 80 1 0 20 0 2 0 28579160 773939200 156115 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944282888 139885998378859 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 110.07
Current children cumulated vsize (KiB) 755800

[startup+115.2 s]
/proc/loadavg: 1.06 1.09 1.02 2/57 22040
/proc/meminfo: memFree=251412/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=756316 CPUtime=111.6
/proc/22034/stat : 22034 (aptitude) R 22033 22034 17863 34816 17863 4202496 159486 2201 355 5 11069 90 1 0 20 0 2 0 28578819 774467584 156466 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921546104 139885998374482 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 302 0 0
/proc/22034/statm: 189079 156466 7191 1052 0 167642 0
[pid=22034/tid=22039] ppid=22033 vsize=756316 CPUtime=108.03
/proc/22034/task/22039/stat : 22039 (aptitude) S 22033 22034 17863 34816 17863 4202560 144788 2201 0 5 10722 80 1 0 20 0 2 0 28579160 774467584 156466 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944289280 139886009627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 111.6
Current children cumulated vsize (KiB) 756316

[startup+115.603 s]
/proc/loadavg: 1.06 1.09 1.02 2/57 22040
/proc/meminfo: memFree=251412/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=756316 CPUtime=112.01
/proc/22034/stat : 22034 (aptitude) R 22033 22034 17863 34816 17863 4202496 161435 2201 355 5 11109 91 1 0 20 0 2 0 28578819 774467584 156420 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921547784 139886035709103 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 302 0 0
/proc/22034/statm: 189079 156420 7192 1052 0 167642 0
[pid=22034/tid=22039] ppid=22033 vsize=756316 CPUtime=108.03
/proc/22034/task/22039/stat : 22039 (aptitude) S 22033 22034 17863 34816 17863 4202560 144788 2201 0 5 10722 80 1 0 20 0 2 0 28579160 774467584 156420 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944289280 139886009627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 112.01
Current children cumulated vsize (KiB) 756316

[startup+115.801 s]
/proc/loadavg: 1.06 1.09 1.02 2/57 22040
/proc/meminfo: memFree=251412/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=756316 CPUtime=112.2
/proc/22034/stat : 22034 (aptitude) R 22033 22034 17863 34816 17863 4202496 162118 2702 355 5 11114 104 1 1 20 0 2 0 28578819 774467584 138968 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921552232 139885998749162 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 302 0 0
/proc/22034/statm: 189079 138968 7192 1052 0 167642 0
[pid=22034/tid=22039] ppid=22033 vsize=756316 CPUtime=108.04
/proc/22034/task/22039/stat : 22039 (aptitude) S 22033 22034 17863 34816 17863 4202560 144788 2702 0 5 10722 80 1 1 20 0 2 0 28579160 774467584 138968 18446744073709551615 139886040883200 139886045190552 140733921555968 139885944289280 139886009627348 0 134217728 4096 0 0 0 0 -1 0 0 0 0 0 0
Current children cumulated CPU time (s) 112.2
Current children cumulated vsize (KiB) 756316

[startup+115.901 s]
/proc/loadavg: 1.06 1.09 1.02 2/57 22040
/proc/meminfo: memFree=251412/1022884 swapFree=0/0
[pid=22034] ppid=22033 vsize=335576 CPUtime=112.3
/proc/22034/stat : 22034 (aptitude) R 22033 22034 17863 34816 17863 4202496 162199 2702 355 5 11114 114 1 1 20 0 1 0 28578819 343629824 37035 18446744073709551615 139886040883200 139886045190552 140733921555968 140733921555528 139885998749162 0 134217728 4096 0 0 0 0 17 0 0 0 302 0 0
/proc/22034/statm: 83894 37035 1521 1052 0 68150 0
Current children cumulated CPU time (s) 112.3
Current children cumulated vsize (KiB) 335576

Child status: 0
Real time (s): 115.947
CPU time (s): 112.359
CPU user time (s): 111.159
CPU system time (s): 1.20007
CPU usage (%): 96.9058
Max. virtual memory (cumulated for all children) (KiB): 756316

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 111.159
system time used= 1.20008
maximum resident set size= 626196
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 164966
page faults= 362
swaps= 0
block input operations= 168752
block output operations= 168
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1861
involuntary context switches= 1953

runsolver used 0.16401 second user time and 0.368023 second system time

The end