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: /home/misc2010/bin/runsolver -s SIGUSR1 -M 1124 -C 290 -d 10 -w /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand394916.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//rand394916.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand394916.cudf.difficult.result 

Enforcing CPUTime limit (soft limit, will send signal-name then SIGKILL): 290 seconds
Enforcing CPUTime limit (hard limit, will send SIGXCPU): 320 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
Current StackSize limit: 8192 KiB


[startup+0 s]
/proc/loadavg: 1.09 1.09 1.03 1/43 18851
/proc/meminfo: memFree=805352/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=3020 CPUtime=0
/proc/18851/stat : 18851 (runsolver) D 18850 18851 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 881221649 3092480 93 1283457024 134512640 134586868 4288859008 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/18851/statm: 755 93 62 19 0 53 0

[startup+0.14972 s]
/proc/loadavg: 1.09 1.09 1.03 1/43 18851
/proc/meminfo: memFree=805352/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2580 CPUtime=0.03
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 881221649 2641920 282 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.209725 s]
/proc/loadavg: 1.09 1.09 1.03 1/43 18851
/proc/meminfo: memFree=805352/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2580 CPUtime=0.03
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 881221649 2641920 282 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.309819 s]
/proc/loadavg: 1.09 1.09 1.03 1/43 18851
/proc/meminfo: memFree=805352/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2580 CPUtime=0.03
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 881221649 2641920 282 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.709932 s]
/proc/loadavg: 1.09 1.09 1.03 1/43 18851
/proc/meminfo: memFree=805352/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2580 CPUtime=0.03
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 881221649 2641920 282 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+1.51007 s]
/proc/loadavg: 1.09 1.09 1.03 2/45 18862
/proc/meminfo: memFree=769416/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2580 CPUtime=0.03
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 881221649 2641920 282 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 645 282 240 194 0 31 0
[pid=18862] ppid=18851 vsize=32760 CPUtime=1.42
/proc/18862/stat : 18862 (cudftodeb.nativ) R 18851 18851 4159 34819 4229 4202496 7769 0 8 0 140 2 0 0 25 0 1 0 881221653 33546240 7704 1283457024 134512640 135004320 4288928816 18446744073709551615 134960225 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18862/statm: 8190 7704 225 121 0 7582 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 35340

[startup+3.11049 s]
/proc/loadavg: 1.09 1.09 1.03 2/45 18862
/proc/meminfo: memFree=747468/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2580 CPUtime=0.03
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 555 1859 0 0 0 0 0 3 25 0 1 0 881221649 2641920 282 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 645 282 240 194 0 31 0
[pid=18862] ppid=18851 vsize=67116 CPUtime=3.01
/proc/18862/stat : 18862 (cudftodeb.nativ) R 18851 18851 4159 34819 4229 4202496 16189 0 8 0 296 5 0 0 25 0 1 0 881221653 68726784 16124 1283457024 134512640 135004320 4288928816 18446744073709551615 134943711 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18862/statm: 16779 16124 237 121 0 16171 0
Current children cumulated CPU time (s) 3.04
Current children cumulated vsize (KiB) 69696

[startup+6.30438 s]
/proc/loadavg: 1.09 1.09 1.03 2/45 18862
/proc/meminfo: memFree=688320/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=5.64
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 635 25889 0 8 0 1 546 17 22 0 1 0 881221649 2650112 285 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 285 241 194 0 33 0
Current children cumulated CPU time (s) 5.64
Current children cumulated vsize (KiB) 2588

[startup+12.7129 s]
/proc/loadavg: 1.08 1.09 1.03 2/46 18875
/proc/meminfo: memFree=697852/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=5.87
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 678 28290 0 9 0 1 566 20 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18872] ppid=18851 vsize=57052 CPUtime=4.17
/proc/18872/stat : 18872 (aptitude) R 18851 18851 4159 34819 4229 4202496 13937 240 342 0 331 86 0 0 25 0 2 0 881222335 58421248 8655 1283457024 134512640 137933492 4289538208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/18872/statm: 14263 8655 5855 836 0 6894 0
[pid=18872/tid=18874] ppid=18851 vsize=57052 CPUtime=0
/proc/18872/task/18874/stat : 18874 (aptitude) S 18851 18851 4159 34819 4229 4202560 3 240 0 0 0 0 0 0 15 0 2 0 881222619 58421248 8655 1283457024 134512640 137933492 4289538208 18446744073709551615 4294960130 0 134217728 4096 0 18446612133362985024 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.04
Current children cumulated vsize (KiB) 59640
heavy processes:

[startup+25.5063 s]
/proc/loadavg: 1.13 1.10 1.03 2/46 18876
/proc/meminfo: memFree=651104/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=5.87
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 678 28290 0 9 0 1 566 20 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18872] ppid=18851 vsize=106088 CPUtime=16.94
/proc/18872/stat : 18872 (aptitude) S 18851 18851 4159 34819 4229 4202496 27206 649 342 0 1529 165 0 0 15 0 2 0 881222335 108634112 20788 1283457024 134512640 137933492 4289538208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/18872/statm: 26522 20788 5972 836 0 19153 0
[pid=18872/tid=18874] ppid=18851 vsize=106088 CPUtime=8.43
/proc/18872/task/18874/stat : 18874 (aptitude) R 18851 18851 4159 34819 4229 4202560 12355 649 0 0 838 5 0 0 25 0 2 0 881222619 108634112 20788 1283457024 134512640 137933492 4289538208 18446744073709551615 135914120 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 22.81
Current children cumulated vsize (KiB) 108676

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

[startup+25.6063 s]
/proc/loadavg: 1.13 1.10 1.03 2/46 18876
/proc/meminfo: memFree=651104/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=5.87
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 678 28290 0 9 0 1 566 20 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18872] ppid=18851 vsize=106484 CPUtime=17.04
/proc/18872/stat : 18872 (aptitude) S 18851 18851 4159 34819 4229 4202496 27290 649 342 0 1539 165 0 0 15 0 2 0 881222335 109039616 20872 1283457024 134512640 137933492 4289538208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/18872/statm: 26621 20872 5972 836 0 19252 0
[pid=18872/tid=18874] ppid=18851 vsize=106484 CPUtime=8.53
/proc/18872/task/18874/stat : 18874 (aptitude) R 18851 18851 4159 34819 4229 4202560 12439 649 0 0 848 5 0 0 25 0 2 0 881222619 109039616 20872 1283457024 134512640 137933492 4289538208 18446744073709551615 135914117 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 22.91
Current children cumulated vsize (KiB) 109072

[startup+32.0081 s]
/proc/loadavg: 1.12 1.10 1.03 2/46 18876
/proc/meminfo: memFree=622956/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=5.87
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 678 28290 0 9 0 1 566 20 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18872] ppid=18851 vsize=134072 CPUtime=23.45
/proc/18872/stat : 18872 (aptitude) S 18851 18851 4159 34819 4229 4202496 34181 649 342 0 2172 173 0 0 15 0 2 0 881222335 137289728 27763 1283457024 134512640 137933492 4289538208 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/18872/statm: 33518 27763 5972 836 0 26149 0
[pid=18872/tid=18874] ppid=18851 vsize=134072 CPUtime=14.94
/proc/18872/task/18874/stat : 18874 (aptitude) R 18851 18851 4159 34819 4229 4202560 19330 649 0 0 1481 13 0 0 25 0 2 0 881222619 137289728 27763 1283457024 134512640 137933492 4289538208 18446744073709551615 136299179 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 29.32
Current children cumulated vsize (KiB) 136660

[startup+35.2061 s]
/proc/loadavg: 1.11 1.10 1.03 3/46 18876
/proc/meminfo: memFree=609508/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=5.87
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 678 28290 0 9 0 1 566 20 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18872] ppid=18851 vsize=146484 CPUtime=26.59
/proc/18872/stat : 18872 (aptitude) R 18851 18851 4159 34819 4229 4202496 37420 649 345 0 2485 174 0 0 16 0 2 0 881222335 149999616 30999 1283457024 134512640 137933492 4289538208 18446744073709551615 4153263740 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/18872/statm: 36621 30999 6018 836 0 29252 0
[pid=18872/tid=18874] ppid=18851 vsize=146484 CPUtime=17.74
/proc/18872/task/18874/stat : 18874 (aptitude) R 18851 18851 4159 34819 4229 4202560 22463 649 1 0 1760 14 0 0 25 0 2 0 881222619 149999616 30999 1283457024 134512640 137933492 4289538208 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 32.46
Current children cumulated vsize (KiB) 149072

[startup+36.808 s]
/proc/loadavg: 1.11 1.10 1.03 2/45 18878
/proc/meminfo: memFree=703532/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=33.24
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 704 68705 0 354 0 1 3121 202 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18878] ppid=18851 vsize=18516 CPUtime=0.72
/proc/18878/stat : 18878 (aptsolutions.na) R 18851 18851 4159 34819 4229 4202496 4281 0 9 0 71 1 0 0 20 0 1 0 881225252 18960384 4178 1283457024 134512640 134971616 4291016112 18446744073709551615 134954332 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18878/statm: 4629 4178 204 113 0 4031 0
Current children cumulated CPU time (s) 33.96
Current children cumulated vsize (KiB) 21104

[startup+37.6083 s]
/proc/loadavg: 1.11 1.10 1.03 2/45 18878
/proc/meminfo: memFree=679972/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=33.24
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 704 68705 0 354 0 1 3121 202 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18878] ppid=18851 vsize=35576 CPUtime=1.51
/proc/18878/stat : 18878 (aptsolutions.na) R 18851 18851 4159 34819 4229 4202496 8418 0 9 0 148 3 0 0 22 0 1 0 881225252 36429824 8315 1283457024 134512640 134971616 4291016112 18446744073709551615 134800390 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18878/statm: 8894 8315 204 113 0 8296 0
Current children cumulated CPU time (s) 34.75
Current children cumulated vsize (KiB) 38164

[startup+38.0084 s]
/proc/loadavg: 1.11 1.10 1.03 2/45 18878
/proc/meminfo: memFree=679972/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=33.24
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 704 68705 0 354 0 1 3121 202 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18878] ppid=18851 vsize=44504 CPUtime=1.91
/proc/18878/stat : 18878 (aptsolutions.na) R 18851 18851 4159 34819 4229 4202496 10661 0 9 0 187 4 0 0 25 0 1 0 881225252 45572096 10558 1283457024 134512640 134971616 4291016112 18446744073709551615 134915789 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18878/statm: 11126 10558 204 113 0 10528 0
Current children cumulated CPU time (s) 35.15
Current children cumulated vsize (KiB) 47092

[startup+38.4086 s]
/proc/loadavg: 1.11 1.10 1.03 2/45 18878
/proc/meminfo: memFree=679972/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=33.24
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 704 68705 0 354 0 1 3121 202 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18878] ppid=18851 vsize=52688 CPUtime=2.31
/proc/18878/stat : 18878 (aptsolutions.na) R 18851 18851 4159 34819 4229 4202496 12635 0 9 0 227 4 0 0 25 0 1 0 881225252 53952512 12532 1283457024 134512640 134971616 4291016112 18446744073709551615 134780264 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18878/statm: 13172 12532 204 113 0 12574 0
Current children cumulated CPU time (s) 35.55
Current children cumulated vsize (KiB) 55276

[startup+38.5086 s]
/proc/loadavg: 1.11 1.10 1.03 2/45 18878
/proc/meminfo: memFree=655544/1048576 swapFree=2077676/2097144
[pid=18851] ppid=18850 vsize=2588 CPUtime=33.24
/proc/18851/stat : 18851 (aptitude-trendy) S 18850 18851 4159 34819 4229 4202496 704 68705 0 354 0 1 3121 202 18 0 1 0 881221649 2650112 293 1283457024 134512640 135304128 4292775952 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/18851/statm: 647 293 249 194 0 33 0
[pid=18878] ppid=18851 vsize=56564 CPUtime=2.41
/proc/18878/stat : 18878 (aptsolutions.na) R 18851 18851 4159 34819 4229 4202496 13610 0 9 0 237 4 0 0 25 0 1 0 881225252 57921536 13507 1283457024 134512640 134971616 4291016112 18446744073709551615 134964125 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/18878/statm: 14141 13507 209 113 0 13543 0
Current children cumulated CPU time (s) 35.65
Current children cumulated vsize (KiB) 59152

Child status: 0
Real time (s): 38.5521
CPU time (s): 35.7102
CPU user time (s): 33.6181
CPU system time (s): 2.09213
CPU usage (%): 92.6286
Max. virtual memory (cumulated for all children) (KiB): 150220

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 33.6181
system time used= 2.09213
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 83763
page faults= 363
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 468
involuntary context switches= 643

runsolver used 0 second user time and 0 second system time

The end