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/201012061533/aptitude-paranoid-1.0/rand847939.cudf.difficult.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/difficult//rand847939.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand847939.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.36 1.23 1.20 5/45 27736
/proc/meminfo: memFree=761800/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2532 CPUtime=0.01
/proc/27736/stat : 27736 (aptitude-parano) R 27735 27736 2059 34821 2220 4194304 172 0 0 0 1 0 0 0 25 0 1 0 876366483 2592768 96 1283457024 134512640 135304128 4292620256 18446744073709551615 4160329636 0 0 0 0 0 0 0 17 0 0 0 0
/proc/27736/statm: 633 96 78 194 0 15 0

[startup+0.120836 s]
/proc/loadavg: 1.36 1.23 1.20 5/45 27736
/proc/meminfo: memFree=761800/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2580 CPUtime=0.03
/proc/27736/stat : 27736 (aptitude-parano) R 27735 27736 2059 34821 2220 4202496 537 1858 0 0 1 0 0 2 25 0 1 0 876366483 2641920 282 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/27736/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.210846 s]
/proc/loadavg: 1.36 1.23 1.20 5/45 27736
/proc/meminfo: memFree=761800/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2580 CPUtime=0.03
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 555 1858 0 0 1 0 0 2 25 0 1 0 876366483 2641920 282 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.31087 s]
/proc/loadavg: 1.36 1.23 1.20 5/45 27736
/proc/meminfo: memFree=761800/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2580 CPUtime=0.03
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 555 1858 0 0 1 0 0 2 25 0 1 0 876366483 2641920 282 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+0.710938 s]
/proc/loadavg: 1.36 1.23 1.20 5/45 27736
/proc/meminfo: memFree=761800/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2580 CPUtime=0.03
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 555 1858 0 0 1 0 0 2 25 0 1 0 876366483 2641920 282 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2580

[startup+1.51109 s]
/proc/loadavg: 1.36 1.23 1.20 2/47 27747
/proc/meminfo: memFree=725840/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2580 CPUtime=0.03
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 555 1858 0 0 1 0 0 2 25 0 1 0 876366483 2641920 282 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 645 282 240 194 0 31 0
[pid=27747] ppid=27736 vsize=34000 CPUtime=1.47
/proc/27747/stat : 27747 (cudftodeb.nativ) R 27736 27736 2059 34821 2220 4202496 8060 0 0 0 144 3 0 0 25 0 1 0 876366487 34816000 7987 1283457024 134512640 135004320 4287734656 18446744073709551615 134986368 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27747/statm: 8500 7987 225 121 0 7892 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36580

[startup+3.11134 s]
/proc/loadavg: 1.36 1.23 1.20 2/47 27747
/proc/meminfo: memFree=703520/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2580 CPUtime=0.03
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 555 1858 0 0 1 0 0 2 25 0 1 0 876366483 2641920 282 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 645 282 240 194 0 31 0
[pid=27747] ppid=27736 vsize=69104 CPUtime=3.07
/proc/27747/stat : 27747 (cudftodeb.nativ) R 27736 27736 2059 34821 2220 4202496 16723 0 0 0 303 4 0 0 25 0 1 0 876366487 70762496 16650 1283457024 134512640 135004320 4287734656 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27747/statm: 17276 16650 237 121 0 16668 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 71684

[startup+6.30513 s]
/proc/loadavg: 1.33 1.23 1.20 2/47 27747
/proc/meminfo: memFree=693228/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.57
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 635 25893 0 0 1 0 538 18 18 0 1 0 876366483 2650112 285 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 285 241 194 0 33 0
Current children cumulated CPU time (s) 5.57
Current children cumulated vsize (KiB) 2588

[startup+12.7055 s]
/proc/loadavg: 1.31 1.22 1.20 2/48 27760
/proc/meminfo: memFree=664592/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.8
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 680 28297 0 1 1 0 556 23 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27757] ppid=27736 vsize=59000 CPUtime=5.25
/proc/27757/stat : 27757 (aptitude) R 27736 27736 2059 34821 2220 4202496 14423 240 266 0 458 67 0 0 25 0 2 0 876367130 60416000 9063 1283457024 134512640 137933492 4288485280 18446744073709551615 4159679644 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27757/statm: 14750 9063 5890 836 0 7382 0
[pid=27757/tid=27759] ppid=27736 vsize=59000 CPUtime=0
/proc/27757/task/27759/stat : 27759 (aptitude) S 27736 27736 2059 34821 2220 4202560 3 240 0 0 0 0 0 0 15 0 2 0 876367356 60416000 9063 1283457024 134512640 137933492 4288485280 18446744073709551615 4294960130 0 134217728 4096 0 18446612132844133376 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.05
Current children cumulated vsize (KiB) 61588

[startup+25.5083 s]
/proc/loadavg: 1.24 1.21 1.19 2/48 27761
/proc/meminfo: memFree=580768/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.8
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 680 28297 0 1 1 0 556 23 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27757] ppid=27736 vsize=144216 CPUtime=18.05
/proc/27757/stat : 27757 (aptitude) S 27736 27736 2059 34821 2220 4202496 36768 650 266 0 1724 80 0 1 15 0 2 0 876367130 147677184 30336 1283457024 134512640 137933492 4288485280 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27757/statm: 36054 30336 5978 836 0 28686 0
[pid=27757/tid=27759] ppid=27736 vsize=144216 CPUtime=12.16
/proc/27757/task/27759/stat : 27759 (aptitude) R 27736 27736 2059 34821 2220 4202560 21870 650 0 0 1203 12 0 1 25 0 2 0 876367356 147677184 30336 1283457024 134512640 137933492 4288485280 18446744073709551615 136467942 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 23.85
Current children cumulated vsize (KiB) 146804

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

[startup+25.6083 s]
/proc/loadavg: 1.24 1.21 1.19 2/48 27761
/proc/meminfo: memFree=580768/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.8
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 680 28297 0 1 1 0 556 23 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27757] ppid=27736 vsize=145008 CPUtime=18.15
/proc/27757/stat : 27757 (aptitude) S 27736 27736 2059 34821 2220 4202496 36942 650 266 0 1734 80 0 1 15 0 2 0 876367130 148488192 30510 1283457024 134512640 137933492 4288485280 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27757/statm: 36252 30510 5978 836 0 28884 0
[pid=27757/tid=27759] ppid=27736 vsize=145008 CPUtime=12.26
/proc/27757/task/27759/stat : 27759 (aptitude) R 27736 27736 2059 34821 2220 4202560 22044 650 0 0 1213 12 0 1 25 0 2 0 876367356 148488192 30510 1283457024 134512640 137933492 4288485280 18446744073709551615 136236576 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 23.95
Current children cumulated vsize (KiB) 147596

[startup+32.0094 s]
/proc/loadavg: 1.22 1.21 1.19 2/48 27761
/proc/meminfo: memFree=540096/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.8
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 680 28297 0 1 1 0 556 23 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27757] ppid=27736 vsize=184148 CPUtime=24.55
/proc/27757/stat : 27757 (aptitude) S 27736 27736 2059 34821 2220 4202496 46724 650 266 0 2372 82 0 1 15 0 2 0 876367130 188567552 40292 1283457024 134512640 137933492 4288485280 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27757/statm: 46037 40292 5978 836 0 38669 0
[pid=27757/tid=27759] ppid=27736 vsize=184148 CPUtime=18.66
/proc/27757/task/27759/stat : 27759 (aptitude) R 27736 27736 2059 34821 2220 4202560 31826 650 0 0 1851 14 0 1 25 0 2 0 876367356 188567552 40292 1283457024 134512640 137933492 4288485280 18446744073709551615 136299512 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 30.35
Current children cumulated vsize (KiB) 186736

[startup+35.2104 s]
/proc/loadavg: 1.20 1.20 1.19 2/48 27761
/proc/meminfo: memFree=521620/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.8
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 680 28297 0 1 1 0 556 23 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27757] ppid=27736 vsize=202164 CPUtime=27.73
/proc/27757/stat : 27757 (aptitude) S 27736 27736 2059 34821 2220 4202496 51219 650 266 0 2689 83 0 1 15 0 2 0 876367130 207015936 44785 1283457024 134512640 137933492 4288485280 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27757/statm: 50541 44785 5979 836 0 43173 0
[pid=27757/tid=27759] ppid=27736 vsize=202164 CPUtime=21.86
/proc/27757/task/27759/stat : 27759 (aptitude) R 27736 27736 2059 34821 2220 4202560 36321 650 0 0 2169 16 0 1 25 0 2 0 876367356 207015936 44785 1283457024 134512640 137933492 4288485280 18446744073709551615 135234618 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 33.53
Current children cumulated vsize (KiB) 204752

[startup+36.8134 s]
/proc/loadavg: 1.20 1.20 1.19 3/48 27761
/proc/meminfo: memFree=519636/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=5.8
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 680 28297 0 1 1 0 556 23 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27757] ppid=27736 vsize=205028 CPUtime=29.33
/proc/27757/stat : 27757 (aptitude) R 27736 27736 2059 34821 2220 4202496 53525 1060 266 0 2844 88 0 1 17 0 2 0 876367130 209948672 45722 1283457024 134512640 137933492 4288485280 18446744073709551615 4159718491 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/27757/statm: 51257 45722 6009 836 0 43889 0
[pid=27757/tid=27759] ppid=27736 vsize=205028 CPUtime=22.22
/proc/27757/task/27759/stat : 27759 (aptitude) R 27736 27736 2059 34821 2220 4202560 36778 1060 0 0 2205 16 0 1 25 0 2 0 876367356 209948672 45722 1283457024 134512640 137933492 4288485280 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 35.13
Current children cumulated vsize (KiB) 207616

[startup+38.4138 s]
/proc/loadavg: 1.20 1.20 1.19 2/47 27763
/proc/meminfo: memFree=668320/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=35.35
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 706 83026 0 267 1 0 3416 118 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27763] ppid=27736 vsize=32716 CPUtime=1.39
/proc/27763/stat : 27763 (aptsolutions.na) R 27736 27736 2059 34821 2220 4202496 7794 0 0 0 137 2 0 0 23 0 1 0 876370185 33501184 7681 1283457024 134512640 134971616 4291165872 18446744073709551615 134953970 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27763/statm: 8179 7681 204 113 0 7581 0
Current children cumulated CPU time (s) 36.74
Current children cumulated vsize (KiB) 35304

[startup+39.204 s]
/proc/loadavg: 1.18 1.20 1.19 2/47 27763
/proc/meminfo: memFree=645876/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=35.35
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 706 83026 0 267 1 0 3416 118 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27763] ppid=27736 vsize=48964 CPUtime=2.18
/proc/27763/stat : 27763 (aptsolutions.na) R 27736 27736 2059 34821 2220 4202496 11725 0 0 0 216 2 0 0 25 0 1 0 876370185 50139136 11612 1283457024 134512640 134971616 4291165872 18446744073709551615 134619550 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27763/statm: 12241 11612 204 113 0 11643 0
Current children cumulated CPU time (s) 37.53
Current children cumulated vsize (KiB) 51552

[startup+39.4041 s]
/proc/loadavg: 1.18 1.20 1.19 2/47 27763
/proc/meminfo: memFree=645876/1048576 swapFree=2078764/2097144
[pid=27736] ppid=27735 vsize=2588 CPUtime=35.35
/proc/27736/stat : 27736 (aptitude-parano) S 27735 27736 2059 34821 2220 4202496 706 83026 0 267 1 0 3416 118 18 0 1 0 876366483 2650112 293 1283457024 134512640 135304128 4292620256 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/27736/statm: 647 293 249 194 0 33 0
[pid=27763] ppid=27736 vsize=54300 CPUtime=2.38
/proc/27763/stat : 27763 (aptsolutions.na) R 27736 27736 2059 34821 2220 4202496 13066 0 0 0 236 2 0 0 25 0 1 0 876370185 55603200 12953 1283457024 134512640 134971616 4291165872 18446744073709551615 134912668 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/27763/statm: 13575 12953 208 113 0 12977 0
Current children cumulated CPU time (s) 37.73
Current children cumulated vsize (KiB) 56888

Child status: 0
Real time (s): 39.4911
CPU time (s): 37.8224
CPU user time (s): 36.6143
CPU system time (s): 1.20807
CPU usage (%): 95.7743
Max. virtual memory (cumulated for all children) (KiB): 207616

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 36.6143
system time used= 1.20808
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 97971
page faults= 267
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 315
involuntary context switches= 736

runsolver used 0 second user time and 0 second system time

The end