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/rand50a937.cudf.difficult.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/difficult//rand50a937.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/rand50a937.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.04 1.04 1.01 3/45 26977
/proc/meminfo: memFree=721356/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=3016 CPUtime=0.02
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 473 0 0 0 2 0 0 0 25 0 1 0 883045253 3088384 400 1283457024 134512640 135004320 4292220880 18446744073709551615 134979025 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 754 400 224 121 0 146 0

[startup+0.187479 s]
/proc/loadavg: 1.04 1.04 1.01 3/45 26977
/proc/meminfo: memFree=721356/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=5992 CPUtime=0.16
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 1203 0 0 0 16 0 0 0 25 0 1 0 883045253 6135808 1130 1283457024 134512640 135004320 4292220880 18446744073709551615 134986543 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 1498 1130 225 121 0 890 0
Current children cumulated CPU time (s) 0.18
Current children cumulated vsize (KiB) 8572

[startup+0.207477 s]
/proc/loadavg: 1.04 1.04 1.01 3/45 26977
/proc/meminfo: memFree=721356/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=6488 CPUtime=0.18
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 1316 0 0 0 18 0 0 0 25 0 1 0 883045253 6643712 1243 1283457024 134512640 135004320 4292220880 18446744073709551615 134959974 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 1622 1243 225 121 0 1014 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 9068

[startup+0.30751 s]
/proc/loadavg: 1.04 1.04 1.01 3/45 26977
/proc/meminfo: memFree=721356/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=8472 CPUtime=0.28
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 1823 0 0 0 28 0 0 0 25 0 1 0 883045253 8675328 1750 1283457024 134512640 135004320 4292220880 18446744073709551615 134826014 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 2118 1750 225 121 0 1510 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 11052

[startup+0.707607 s]
/proc/loadavg: 1.04 1.04 1.01 3/45 26977
/proc/meminfo: memFree=721356/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=17312 CPUtime=0.67
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 3960 0 0 0 66 1 0 0 25 0 1 0 883045253 17727488 3887 1283457024 134512640 135004320 4292220880 18446744073709551615 134946279 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 4328 3887 225 121 0 3720 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 19892

[startup+1.50784 s]
/proc/loadavg: 1.04 1.04 1.01 2/46 26978
/proc/meminfo: memFree=699292/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=33500 CPUtime=1.48
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 7960 0 0 0 146 2 0 0 25 0 1 0 883045253 34304000 7887 1283457024 134512640 135004320 4292220880 18446744073709551615 134996526 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 8375 7887 225 121 0 7767 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36080

[startup+3.10826 s]
/proc/loadavg: 1.04 1.04 1.01 2/46 26978
/proc/meminfo: memFree=676972/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2580 CPUtime=0.02
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 566 1859 0 0 0 0 0 2 25 0 1 0 883045250 2641920 283 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 645 283 240 194 0 31 0
[pid=26977] ppid=26967 vsize=68608 CPUtime=3.08
/proc/26977/stat : 26977 (cudftodeb.nativ) R 26967 26967 4159 34819 4229 4202496 16544 0 0 0 306 2 0 0 25 0 1 0 883045253 70254592 16471 1283457024 134512640 135004320 4292220880 18446744073709551615 134867636 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26977/statm: 17152 16471 237 121 0 16544 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 71188

[startup+6.3073 s]
/proc/loadavg: 1.04 1.04 1.01 2/46 26978
/proc/meminfo: memFree=619064/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=5.58
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 650 25900 0 0 0 0 539 19 20 0 1 0 883045250 2650112 286 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 286 241 194 0 33 0
Current children cumulated CPU time (s) 5.58
Current children cumulated vsize (KiB) 2588

[startup+12.7043 s]
/proc/loadavg: 1.04 1.04 1.01 3/47 26992
/proc/meminfo: memFree=624196/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=5.81
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 695 28298 0 1 0 0 558 23 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26988] ppid=26967 vsize=72000 CPUtime=5.15
/proc/26988/stat : 26988 (aptitude) R 26967 26967 4159 34819 4229 4202496 18748 650 286 0 502 12 0 1 23 0 2 0 883045902 73728000 12250 1283457024 134512640 137933492 4287086144 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/26988/statm: 18000 12250 5708 836 0 10639 0
[pid=26988/tid=26990] ppid=26967 vsize=72000 CPUtime=1.79
/proc/26988/task/26990/stat : 26990 (aptitude) R 26967 26967 4159 34819 4229 4202560 4080 650 1 0 176 2 0 1 17 0 2 0 883046129 73728000 12250 1283457024 134512640 137933492 4287086144 18446744073709551615 4153255742 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.96
Current children cumulated vsize (KiB) 74588

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

[startup+12.8043 s]
/proc/loadavg: 1.04 1.04 1.01 3/47 26992
/proc/meminfo: memFree=624196/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=5.81
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 695 28298 0 1 0 0 558 23 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26988] ppid=26967 vsize=72556 CPUtime=5.25
/proc/26988/stat : 26988 (aptitude) R 26967 26967 4159 34819 4229 4202496 18954 650 286 0 512 12 0 1 23 0 2 0 883045902 74297344 12452 1283457024 134512640 137933492 4287086144 18446744073709551615 136277323 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/26988/statm: 18139 12452 5759 836 0 10771 0
[pid=26988/tid=26990] ppid=26967 vsize=72556 CPUtime=1.88
/proc/26988/task/26990/stat : 26990 (aptitude) S 26967 26967 4159 34819 4229 4202560 4179 650 1 0 185 2 0 1 18 0 2 0 883046129 74297344 12452 1283457024 134512640 137933492 4287086144 18446744073709551615 4294960130 0 134217728 4096 0 18446612132844133376 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.06
Current children cumulated vsize (KiB) 75144

[startup+14.4047 s]
/proc/loadavg: 1.04 1.04 1.01 2/46 26994
/proc/meminfo: memFree=635364/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=11.98
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 721 50221 0 287 0 0 1160 38 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26994] ppid=26967 vsize=17764 CPUtime=0.68
/proc/26994/stat : 26994 (aptsolutions.na) R 26967 26967 4159 34819 4229 4202496 4097 0 0 0 66 2 0 0 24 0 1 0 883046622 18190336 3985 1283457024 134512640 134971616 4293579008 18446744073709551615 134915860 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26994/statm: 4441 3985 204 113 0 3843 0
Current children cumulated CPU time (s) 12.66
Current children cumulated vsize (KiB) 20352

[startup+15.2051 s]
/proc/loadavg: 1.04 1.04 1.01 2/46 26994
/proc/meminfo: memFree=635364/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=11.98
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 721 50221 0 287 0 0 1160 38 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26994] ppid=26967 vsize=34200 CPUtime=1.48
/proc/26994/stat : 26994 (aptsolutions.na) R 26967 26967 4159 34819 4229 4202496 8135 0 0 0 144 4 0 0 25 0 1 0 883046622 35020800 8023 1283457024 134512640 134971616 4293579008 18446744073709551615 134800422 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26994/statm: 8550 8023 204 113 0 7952 0
Current children cumulated CPU time (s) 13.46
Current children cumulated vsize (KiB) 36788

[startup+15.6052 s]
/proc/loadavg: 1.03 1.04 1.01 2/46 26994
/proc/meminfo: memFree=612548/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=11.98
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 721 50221 0 287 0 0 1160 38 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26994] ppid=26967 vsize=43256 CPUtime=1.88
/proc/26994/stat : 26994 (aptsolutions.na) R 26967 26967 4159 34819 4229 4202496 10334 0 0 0 184 4 0 0 25 0 1 0 883046622 44294144 10222 1283457024 134512640 134971616 4293579008 18446744073709551615 134912812 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26994/statm: 10814 10222 204 113 0 10216 0
Current children cumulated CPU time (s) 13.86
Current children cumulated vsize (KiB) 45844

[startup+16.0053 s]
/proc/loadavg: 1.03 1.04 1.01 2/46 26994
/proc/meminfo: memFree=612548/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=11.98
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 721 50221 0 287 0 0 1160 38 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26994] ppid=26967 vsize=50944 CPUtime=2.28
/proc/26994/stat : 26994 (aptsolutions.na) R 26967 26967 4159 34819 4229 4202496 12219 0 0 0 222 6 0 0 25 0 1 0 883046622 52166656 12107 1283457024 134512640 134971616 4293579008 18446744073709551615 134800770 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26994/statm: 12736 12107 204 113 0 12138 0
Current children cumulated CPU time (s) 14.26
Current children cumulated vsize (KiB) 53532

[startup+16.1053 s]
/proc/loadavg: 1.03 1.04 1.01 2/46 26994
/proc/meminfo: memFree=612548/1048576 swapFree=2077608/2097144
[pid=26967] ppid=26966 vsize=2588 CPUtime=11.98
/proc/26967/stat : 26967 (aptitude-trendy) S 26966 26967 4159 34819 4229 4202496 721 50221 0 287 0 0 1160 38 18 0 1 0 883045250 2650112 294 1283457024 134512640 135304128 4294199648 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26967/statm: 647 294 249 194 0 33 0
[pid=26994] ppid=26967 vsize=53800 CPUtime=2.38
/proc/26994/stat : 26994 (aptsolutions.na) R 26967 26967 4159 34819 4229 4202496 12977 0 0 0 232 6 0 0 25 0 1 0 883046622 55091200 12865 1283457024 134512640 134971616 4293579008 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26994/statm: 13450 12865 208 113 0 12852 0
Current children cumulated CPU time (s) 14.36
Current children cumulated vsize (KiB) 56388

Child status: 0
Real time (s): 16.201
CPU time (s): 14.4769
CPU user time (s): 14.0129
CPU system time (s): 0.464029
CPU usage (%): 89.3579
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.0129
system time used= 0.464029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 65156
page faults= 287
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 302
involuntary context switches= 399

runsolver used 0 second user time and 0.004 second system time

The end