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/cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf.debian-dudf.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: 0.98 1.03 1.00 1/40 2942
/proc/meminfo: memFree=679568/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=3024 CPUtime=0
/proc/2942/stat : 2942 (runsolver) D 2941 2942 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 885077231 3096576 94 1283457024 134512640 134586868 4287922768 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/2942/statm: 756 94 62 19 0 54 0

[startup+0.190393 s]
/proc/loadavg: 0.98 1.03 1.00 1/40 2942
/proc/meminfo: memFree=679568/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2580 CPUtime=0.02
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 562 1858 0 0 0 0 0 2 25 0 1 0 885077231 2641920 283 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.210394 s]
/proc/loadavg: 0.98 1.03 1.00 1/40 2942
/proc/meminfo: memFree=679568/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2580 CPUtime=0.02
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 562 1858 0 0 0 0 0 2 25 0 1 0 885077231 2641920 283 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.310413 s]
/proc/loadavg: 0.98 1.03 1.00 1/40 2942
/proc/meminfo: memFree=679568/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2580 CPUtime=0.02
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 562 1858 0 0 0 0 0 2 25 0 1 0 885077231 2641920 283 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+0.710499 s]
/proc/loadavg: 0.98 1.03 1.00 1/40 2942
/proc/meminfo: memFree=679568/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2580 CPUtime=0.02
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 562 1858 0 0 0 0 0 2 25 0 1 0 885077231 2641920 283 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 645 283 240 194 0 31 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2580

[startup+1.5107 s]
/proc/loadavg: 0.98 1.02 1.00 2/42 2953
/proc/meminfo: memFree=649584/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2580 CPUtime=0.02
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 562 1858 0 0 0 0 0 2 25 0 1 0 885077231 2641920 283 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 645 283 240 194 0 31 0
[pid=2953] ppid=2942 vsize=30528 CPUtime=1.44
/proc/2953/stat : 2953 (cudftodeb.nativ) R 2942 2942 4159 34819 4229 4202496 7217 0 8 0 140 4 0 0 25 0 1 0 885077234 31260672 7152 1283457024 134512640 135004320 4287305392 18446744073709551615 134948016 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2953/statm: 7632 7152 225 121 0 7024 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 33108

[startup+3.11102 s]
/proc/loadavg: 0.98 1.02 1.00 2/42 2953
/proc/meminfo: memFree=626148/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2580 CPUtime=0.02
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 562 1858 0 0 0 0 0 2 25 0 1 0 885077231 2641920 283 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 645 283 240 194 0 31 0
[pid=2953] ppid=2942 vsize=28828 CPUtime=3.05
/proc/2953/stat : 2953 (cudftodeb.nativ) R 2942 2942 4159 34819 4229 4202496 11700 0 8 0 297 8 0 0 25 0 1 0 885077234 29519872 6755 1283457024 134512640 135004320 4287305392 18446744073709551615 4159309399 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2953/statm: 7207 6755 237 121 0 6599 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 31408

[startup+6.30462 s]
/proc/loadavg: 0.98 1.02 1.00 1/42 2964
/proc/meminfo: memFree=622540/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=3.46
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 688 17328 0 9 0 0 331 15 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2963] ppid=2942 vsize=39404 CPUtime=1.07
/proc/2963/stat : 2963 (aptitude) R 2942 2942 4159 34819 4229 4202496 9140 240 229 0 101 6 0 0 19 0 2 0 885077650 40349696 6052 1283457024 134512640 137933492 4288577040 18446744073709551615 4153965523 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2963/statm: 9851 6052 3752 836 0 4313 0
Current children cumulated CPU time (s) 4.53
Current children cumulated vsize (KiB) 41992
heavy processes:

[startup+12.7109 s]
/proc/loadavg: 0.98 1.02 1.00 2/43 2967
/proc/meminfo: memFree=563180/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=3.46
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 688 17328 0 9 0 0 331 15 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2963] ppid=2942 vsize=100740 CPUtime=7.44
/proc/2963/stat : 2963 (aptitude) S 2942 2942 4159 34819 4229 4202496 22927 650 236 0 734 10 0 0 15 0 2 0 885077650 103157760 19257 1283457024 134512640 137933492 4288577040 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2963/statm: 25185 19257 3960 836 0 19647 0
[pid=2963/tid=2965] ppid=2942 vsize=100740 CPUtime=5.92
/proc/2963/task/2965/stat : 2965 (aptitude) R 2942 2942 4159 34819 4229 4202560 13172 650 0 0 591 1 0 0 25 0 2 0 885077827 103157760 19257 1283457024 134512640 137933492 4288577040 18446744073709551615 136247328 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.9
Current children cumulated vsize (KiB) 103328

[startup+25.5054 s]
/proc/loadavg: 0.98 1.02 1.00 2/43 2967
/proc/meminfo: memFree=465096/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=3.46
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 688 17328 0 9 0 0 331 15 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2963] ppid=2942 vsize=195872 CPUtime=20.19
/proc/2963/stat : 2963 (aptitude) S 2942 2942 4159 34819 4229 4202496 46716 650 237 0 1994 25 0 0 15 0 2 0 885077650 200572928 43045 1283457024 134512640 137933492 4288577040 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2963/statm: 48968 43045 3975 836 0 43430 0
[pid=2963/tid=2965] ppid=2942 vsize=195872 CPUtime=18.67
/proc/2963/task/2965/stat : 2965 (aptitude) R 2942 2942 4159 34819 4229 4202560 36954 650 1 0 1851 16 0 0 25 0 2 0 885077827 200572928 43045 1283457024 134512640 137933492 4288577040 18446744073709551615 136468427 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 23.65
Current children cumulated vsize (KiB) 198460

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

[startup+25.6054 s]
/proc/loadavg: 0.98 1.02 1.00 2/43 2967
/proc/meminfo: memFree=465096/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=3.46
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 688 17328 0 9 0 0 331 15 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2963] ppid=2942 vsize=196664 CPUtime=20.29
/proc/2963/stat : 2963 (aptitude) S 2942 2942 4159 34819 4229 4202496 46910 650 237 0 2004 25 0 0 15 0 2 0 885077650 201383936 43239 1283457024 134512640 137933492 4288577040 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2963/statm: 49166 43239 3975 836 0 43628 0
[pid=2963/tid=2965] ppid=2942 vsize=196664 CPUtime=18.77
/proc/2963/task/2965/stat : 2965 (aptitude) R 2942 2942 4159 34819 4229 4202560 37148 650 1 0 1861 16 0 0 25 0 2 0 885077827 201383936 43239 1283457024 134512640 137933492 4288577040 18446744073709551615 136262096 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 23.75
Current children cumulated vsize (KiB) 199252

[startup+28.8061 s]
/proc/loadavg: 0.98 1.02 1.00 2/43 2967
/proc/meminfo: memFree=440792/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=3.46
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 688 17328 0 9 0 0 331 15 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2963] ppid=2942 vsize=220080 CPUtime=23.47
/proc/2963/stat : 2963 (aptitude) S 2942 2942 4159 34819 4229 4202496 52752 650 237 0 2318 29 0 0 15 0 2 0 885077650 225361920 49081 1283457024 134512640 137933492 4288577040 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2963/statm: 55020 49081 3975 836 0 49482 0
[pid=2963/tid=2965] ppid=2942 vsize=220080 CPUtime=21.96
/proc/2963/task/2965/stat : 2965 (aptitude) R 2942 2942 4159 34819 4229 4202560 42990 650 1 0 2175 21 0 0 25 0 2 0 885077827 225361920 49081 1283457024 134512640 137933492 4288577040 18446744073709551615 136277296 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 26.93
Current children cumulated vsize (KiB) 222668

[startup+30.4092 s]
/proc/loadavg: 0.98 1.02 1.00 2/43 2967
/proc/meminfo: memFree=432608/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=3.46
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 688 17328 0 9 0 0 331 15 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2963] ppid=2942 vsize=227244 CPUtime=25.05
/proc/2963/stat : 2963 (aptitude) R 2942 2942 4159 34819 4229 4202496 54708 650 239 0 2472 33 0 0 16 0 2 0 885077650 232697856 50938 1283457024 134512640 137933492 4288577040 18446744073709551615 4153927292 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/2963/statm: 56811 50938 4028 836 0 51266 0
[pid=2963/tid=2965] ppid=2942 vsize=227244 CPUtime=22.98
/proc/2963/task/2965/stat : 2965 (aptitude) R 2942 2942 4159 34819 4229 4202560 44875 650 1 0 2273 25 0 0 25 0 2 0 885077827 232697856 50938 1283457024 134512640 137933492 4288577040 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 28.51
Current children cumulated vsize (KiB) 229832

[startup+32.0099 s]
/proc/loadavg: 1.07 1.04 1.01 2/42 2969
/proc/meminfo: memFree=601528/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=29.08
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 714 74666 0 248 0 0 2852 56 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2969] ppid=2942 vsize=22728 CPUtime=0.98
/proc/2969/stat : 2969 (aptsolutions.na) R 2942 2942 4159 34819 4229 4202496 5297 0 9 0 94 4 0 0 21 0 1 0 885080328 23273472 5195 1283457024 134512640 134971616 4291761936 18446744073709551615 134927600 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2969/statm: 5682 5195 204 113 0 5084 0
Current children cumulated CPU time (s) 30.06
Current children cumulated vsize (KiB) 25316

[startup+32.8101 s]
/proc/loadavg: 1.07 1.04 1.01 2/42 2969
/proc/meminfo: memFree=601528/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=29.08
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 714 74666 0 248 0 0 2852 56 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2969] ppid=2942 vsize=40344 CPUtime=1.78
/proc/2969/stat : 2969 (aptsolutions.na) R 2942 2942 4159 34819 4229 4202496 9640 0 9 0 172 6 0 0 23 0 1 0 885080328 41312256 9538 1283457024 134512640 134971616 4291761936 18446744073709551615 134820848 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2969/statm: 10086 9538 209 113 0 9488 0
Current children cumulated CPU time (s) 30.86
Current children cumulated vsize (KiB) 42932

[startup+33.0102 s]
/proc/loadavg: 1.07 1.04 1.01 2/42 2969
/proc/meminfo: memFree=569908/1048576 swapFree=2080276/2097144
[pid=2942] ppid=2941 vsize=2588 CPUtime=29.08
/proc/2942/stat : 2942 (aptitude-trendy) S 2941 2942 4159 34819 4229 4202496 714 74666 0 248 0 0 2852 56 18 0 1 0 885077231 2650112 294 1283457024 134512640 135304128 4289350800 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/2942/statm: 647 294 249 194 0 33 0
[pid=2969] ppid=2942 vsize=53856 CPUtime=1.99
/proc/2969/stat : 2969 (aptsolutions.na) R 2942 2942 4159 34819 4229 4202496 12585 0 9 0 192 7 0 0 25 0 1 0 885080328 55148544 12477 1283457024 134512640 134971616 4291761936 18446744073709551615 134908004 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/2969/statm: 13464 12477 209 113 0 12866 0
Current children cumulated CPU time (s) 31.07
Current children cumulated vsize (KiB) 56444

Child status: 0
Real time (s): 33.0257
CPU time (s): 31.0939
CPU user time (s): 30.4459
CPU system time (s): 0.64804
CPU usage (%): 94.1507
Max. virtual memory (cumulated for all children) (KiB): 230496

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 30.4459
system time used= 0.64804
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 88180
page faults= 257
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 371
involuntary context switches= 464

runsolver used 0 second user time and 0.004 second system time

The end