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/randf17677.cudf.difficult.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/difficult//randf17677.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/randf17677.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.52 1.46 1.33 6/39 2937
/proc/meminfo: memFree=659212/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2576 CPUtime=0
/proc/2936/stat : 2936 (aptitude-parano) R 2935 2936 2059 34821 2220 4202496 359 0 0 0 0 0 0 0 25 0 1 0 876732626 2637824 272 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/2936/statm: 644 272 232 194 0 30 0
[pid=2937] ppid=2936 vsize=2576 CPUtime=0
/proc/2937/stat : 2937 (aptitude-parano) R 2936 2936 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 876732626 2637824 40 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/2937/statm: 644 40 0 194 0 30 0

[startup+0.141829 s]
/proc/loadavg: 1.52 1.46 1.33 6/39 2937
/proc/meminfo: memFree=659212/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2588 CPUtime=0.03
/proc/2936/stat : 2936 (aptitude-parano) R 2935 2936 2059 34821 2220 4202496 548 1862 0 0 0 0 0 3 25 0 1 0 876732626 2650112 283 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/2936/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.211844 s]
/proc/loadavg: 1.52 1.46 1.33 6/39 2937
/proc/meminfo: memFree=659212/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2588 CPUtime=0.03
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876732626 2650112 283 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.311864 s]
/proc/loadavg: 1.52 1.46 1.33 6/39 2937
/proc/meminfo: memFree=659212/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2588 CPUtime=0.03
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876732626 2650112 283 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.711929 s]
/proc/loadavg: 1.52 1.46 1.33 6/39 2937
/proc/meminfo: memFree=659212/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2588 CPUtime=0.03
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876732626 2650112 283 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+1.51206 s]
/proc/loadavg: 1.52 1.46 1.33 2/40 2947
/proc/meminfo: memFree=624044/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2588 CPUtime=0.03
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876732626 2650112 283 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 647 283 240 194 0 33 0
[pid=2947] ppid=2936 vsize=33256 CPUtime=1.47
/proc/2947/stat : 2947 (cudftodeb.nativ) R 2936 2936 2059 34821 2220 4202496 7867 0 0 0 142 5 0 0 25 0 1 0 876732630 34054144 7793 1283457024 134512640 135004320 4289457456 18446744073709551615 134940187 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2947/statm: 8314 7793 225 121 0 7706 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 35844

[startup+3.11258 s]
/proc/loadavg: 1.48 1.45 1.32 2/40 2947
/proc/meminfo: memFree=602220/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2588 CPUtime=0.03
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876732626 2650112 283 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 647 283 240 194 0 33 0
[pid=2947] ppid=2936 vsize=67616 CPUtime=3.06
/proc/2947/stat : 2947 (cudftodeb.nativ) R 2936 2936 2059 34821 2220 4202496 16357 0 0 0 300 6 0 0 25 0 1 0 876732630 69238784 16283 1283457024 134512640 135004320 4289457456 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2947/statm: 16904 16283 237 121 0 16296 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 70204

[startup+6.30417 s]
/proc/loadavg: 1.48 1.45 1.32 2/40 2947
/proc/meminfo: memFree=543692/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=5.61
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 647 25898 0 0 0 0 542 19 18 0 1 0 876732626 2658304 286 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 286 241 194 0 35 0
Current children cumulated CPU time (s) 5.61
Current children cumulated vsize (KiB) 2596

[startup+12.7143 s]
/proc/loadavg: 1.40 1.44 1.32 2/41 2960
/proc/meminfo: memFree=562372/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=5.86
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 693 28298 0 1 0 0 564 22 18 0 1 0 876732626 2658304 294 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 294 249 194 0 35 0
[pid=2957] ppid=2936 vsize=58252 CPUtime=5.2
/proc/2957/stat : 2957 (aptitude) R 2936 2936 2059 34821 2220 4202496 14365 241 267 0 438 82 0 0 25 0 2 0 876733284 59650048 9006 1283457024 134512640 137933492 4288597888 18446744073709551615 135915492 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2957/statm: 14563 9006 5882 836 0 7195 0
[pid=2957/tid=2959] ppid=2936 vsize=58252 CPUtime=0
/proc/2957/task/2959/stat : 2959 (aptitude) S 2936 2936 2059 34821 2220 4202560 3 241 0 0 0 0 0 0 15 0 2 0 876733508 59650048 9006 1283457024 134512640 137933492 4288597888 18446744073709551615 4294960130 0 134217728 4096 0 18446612133395920896 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.06
Current children cumulated vsize (KiB) 60848

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

[startup+12.8144 s]
/proc/loadavg: 1.40 1.44 1.32 2/41 2960
/proc/meminfo: memFree=562372/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=5.86
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 693 28298 0 1 0 0 564 22 18 0 1 0 876732626 2658304 294 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 294 249 194 0 35 0
[pid=2957] ppid=2936 vsize=58168 CPUtime=5.29
/proc/2957/stat : 2957 (aptitude) R 2936 2936 2059 34821 2220 4202496 14859 651 267 0 446 83 0 0 25 0 2 0 876733284 59564032 8986 1283457024 134512640 137933492 4288597888 18446744073709551615 135958567 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2957/statm: 14542 8986 5910 836 0 7174 0
[pid=2957/tid=2959] ppid=2936 vsize=58168 CPUtime=0
/proc/2957/task/2959/stat : 2959 (aptitude) S 2936 2936 2059 34821 2220 4202560 5 651 0 0 0 0 0 0 15 0 2 0 876733508 59564032 8986 1283457024 134512640 137933492 4288597888 18446744073709551615 4294960130 0 134217728 4096 0 18446612133395920896 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.15
Current children cumulated vsize (KiB) 60764

[startup+14.4047 s]
/proc/loadavg: 1.40 1.44 1.32 2/41 2962
/proc/meminfo: memFree=556420/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=5.86
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 693 28298 0 1 0 0 564 22 18 0 1 0 876732626 2658304 294 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 294 249 194 0 35 0
[pid=2957] ppid=2936 vsize=63848 CPUtime=6.88
/proc/2957/stat : 2957 (aptitude) R 2936 2936 2059 34821 2220 4202496 18716 1061 267 0 603 85 0 0 25 0 2 0 876733284 65380352 10520 1283457024 134512640 137933492 4288597888 18446744073709551615 4159706203 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2957/statm: 15962 10520 5996 836 0 8594 0
[pid=2957/tid=2959] ppid=2936 vsize=63848 CPUtime=0.43
/proc/2957/task/2959/stat : 2959 (aptitude) S 2936 2936 2059 34821 2220 4202560 2008 1061 0 0 42 1 0 0 16 0 2 0 876733508 65380352 10520 1283457024 134512640 137933492 4288597888 18446744073709551615 4294960130 0 134217728 4096 0 18446612133395920896 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 12.74
Current children cumulated vsize (KiB) 66444

[startup+16.0051 s]
/proc/loadavg: 1.40 1.44 1.32 2/40 2963
/proc/meminfo: memFree=556056/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=12.89
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 721 48174 0 268 0 0 1181 108 18 0 1 0 876732626 2658304 294 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 294 249 194 0 35 0
[pid=2963] ppid=2936 vsize=33456 CPUtime=1.44
/proc/2963/stat : 2963 (aptsolutions.na) R 2936 2936 2059 34821 2220 4202496 7965 0 0 0 140 4 0 0 25 0 1 0 876734082 34258944 7851 1283457024 134512640 134971616 4292476912 18446744073709551615 134919374 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2963/statm: 8364 7851 204 113 0 7766 0
Current children cumulated CPU time (s) 14.33
Current children cumulated vsize (KiB) 36052

[startup+16.8053 s]
/proc/loadavg: 1.40 1.44 1.32 2/40 2963
/proc/meminfo: memFree=532992/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=12.89
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 721 48174 0 268 0 0 1181 108 18 0 1 0 876732626 2658304 294 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 294 249 194 0 35 0
[pid=2963] ppid=2936 vsize=50448 CPUtime=2.24
/proc/2963/stat : 2963 (aptsolutions.na) R 2936 2936 2059 34821 2220 4202496 12117 0 0 0 219 5 0 0 25 0 1 0 876734082 51658752 12003 1283457024 134512640 134971616 4292476912 18446744073709551615 134917422 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2963/statm: 12612 12003 204 113 0 12014 0
Current children cumulated CPU time (s) 15.13
Current children cumulated vsize (KiB) 53044

[startup+17.0053 s]
/proc/loadavg: 1.40 1.44 1.32 2/40 2963
/proc/meminfo: memFree=532992/1048576 swapFree=2084004/2097144
[pid=2936] ppid=2935 vsize=2596 CPUtime=12.89
/proc/2936/stat : 2936 (aptitude-parano) S 2935 2936 2059 34821 2220 4202496 721 48174 0 268 0 0 1181 108 18 0 1 0 876732626 2658304 294 1283457024 134512640 135304128 4287480560 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2936/statm: 649 294 249 194 0 35 0
[pid=2963] ppid=2936 vsize=57644 CPUtime=2.44
/proc/2963/stat : 2963 (aptsolutions.na) R 2936 2936 2059 34821 2220 4202496 13869 0 0 0 239 5 0 0 25 0 1 0 876734082 59027456 13755 1283457024 134512640 134971616 4292476912 18446744073709551615 134911465 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2963/statm: 14411 13755 209 113 0 13813 0
Current children cumulated CPU time (s) 15.33
Current children cumulated vsize (KiB) 60240

Child status: 0
Real time (s): 17.0205
CPU time (s): 15.365
CPU user time (s): 14.2169
CPU system time (s): 1.14807
CPU usage (%): 90.2733
Max. virtual memory (cumulated for all children) (KiB): 111012

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.2169
system time used= 1.14807
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 63057
page faults= 268
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 323
involuntary context switches= 414

runsolver used 0 second user time and 0 second system time

The end