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/29180036-5408-11df-9f57-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//29180036-5408-11df-9f57-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/29180036-5408-11df-9f57-00163e7a6f5e.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.86 0.97 0.99 5/41 13462
/proc/meminfo: memFree=804884/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 519 1364 0 0 0 0 0 0 18 0 1 0 879774808 2650112 281 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 281 237 194 0 33 0
[pid=13462] ppid=13454 vsize=2004 CPUtime=0.01
/proc/13462/stat : 13462 (cp) R 13454 13454 4159 34819 4229 4202496 255 0 0 0 0 1 0 0 25 0 1 0 879774809 2052096 183 1283457024 134512640 134614052 4291465024 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/13462/statm: 501 183 145 25 0 47 0

[startup+0.172678 s]
/proc/loadavg: 0.86 0.97 0.99 5/41 13462
/proc/meminfo: memFree=804884/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0.04
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 568 1864 0 0 0 0 0 4 25 0 1 0 879774808 2650112 284 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+0.202684 s]
/proc/loadavg: 0.86 0.97 0.99 5/41 13462
/proc/meminfo: memFree=804884/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0.04
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 568 1864 0 0 0 0 0 4 25 0 1 0 879774808 2650112 284 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+0.312727 s]
/proc/loadavg: 0.86 0.97 0.99 5/41 13462
/proc/meminfo: memFree=804884/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0.04
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 568 1864 0 0 0 0 0 4 25 0 1 0 879774808 2650112 284 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+0.712864 s]
/proc/loadavg: 0.86 0.97 0.99 5/41 13462
/proc/meminfo: memFree=804884/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0.04
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 568 1864 0 0 0 0 0 4 25 0 1 0 879774808 2650112 284 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2588

[startup+1.51318 s]
/proc/loadavg: 0.86 0.97 0.99 2/42 13465
/proc/meminfo: memFree=775600/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0.04
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 568 1864 0 0 0 0 0 4 25 0 1 0 879774808 2650112 284 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 284 240 194 0 33 0
[pid=13465] ppid=13454 vsize=30708 CPUtime=1.47
/proc/13465/stat : 13465 (cudftodeb.nativ) R 13454 13454 4159 34819 4229 4202496 7221 0 0 0 143 4 0 0 25 0 1 0 879774812 31444992 7147 1283457024 134512640 135004320 4294515184 18446744073709551615 134978023 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/13465/statm: 7677 7147 225 121 0 7069 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 33296

[startup+3.11359 s]
/proc/loadavg: 0.87 0.97 0.99 2/42 13465
/proc/meminfo: memFree=752660/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2588 CPUtime=0.04
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 568 1864 0 0 0 0 0 4 25 0 1 0 879774808 2650112 284 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 647 284 240 194 0 33 0
[pid=13465] ppid=13454 vsize=60504 CPUtime=3.07
/proc/13465/stat : 13465 (cudftodeb.nativ) R 13454 13454 4159 34819 4229 4202496 14629 0 0 0 302 5 0 0 25 0 1 0 879774812 61956096 14555 1283457024 134512640 135004320 4294515184 18446744073709551615 134947997 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/13465/statm: 15126 14555 237 121 0 14518 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 63092

[startup+6.31034 s]
/proc/loadavg: 0.87 0.97 0.99 2/42 13476
/proc/meminfo: memFree=750180/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2596 CPUtime=3.41
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 695 19666 0 1 0 0 329 12 18 0 1 0 879774808 2658304 295 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 649 295 249 194 0 35 0
[pid=13475] ppid=13454 vsize=47432 CPUtime=1.44
/proc/13475/stat : 13475 (aptitude) R 13454 13454 4159 34819 4229 4202496 9414 648 153 0 138 6 0 0 21 0 2 0 879775237 48570368 6137 1283457024 134512640 137933492 4292722080 18446744073709551615 4154682932 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/13475/statm: 11858 6137 3749 836 0 6487 0
Current children cumulated CPU time (s) 4.85
Current children cumulated vsize (KiB) 50028
heavy processes:

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

[startup+6.42036 s]
/proc/loadavg: 0.87 0.97 0.99 2/43 13479
/proc/meminfo: memFree=746328/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2596 CPUtime=3.41
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 695 19666 0 1 0 0 329 12 18 0 1 0 879774808 2658304 295 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 649 295 249 194 0 35 0
[pid=13475] ppid=13454 vsize=48620 CPUtime=1.56
/proc/13475/stat : 13475 (aptitude) R 13454 13454 4159 34819 4229 4202496 10016 648 153 0 150 6 0 0 21 0 2 0 879775237 49786880 6510 1283457024 134512640 137933492 4292722080 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/13475/statm: 12155 6510 3805 836 0 6784 0
[pid=13475/tid=13477] ppid=13454 vsize=48620 CPUtime=0.08
/proc/13475/task/13477/stat : 13477 (aptitude) R 13454 13454 4159 34819 4229 4202560 604 648 0 0 8 0 0 0 15 0 2 0 879775370 49786880 6510 1283457024 134512640 137933492 4292722080 18446744073709551615 136298028 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.97
Current children cumulated vsize (KiB) 51216

[startup+7.21059 s]
/proc/loadavg: 0.87 0.97 0.99 2/43 13480
/proc/meminfo: memFree=744468/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2596 CPUtime=5.22
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 722 32394 0 154 0 0 502 20 18 0 1 0 879774808 2658304 295 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 649 295 249 194 0 35 0
Current children cumulated CPU time (s) 5.22
Current children cumulated vsize (KiB) 2596

[startup+8.01078 s]
/proc/loadavg: 0.88 0.97 0.99 2/42 13481
/proc/meminfo: memFree=735796/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2596 CPUtime=5.22
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 722 32394 0 154 0 0 502 20 18 0 1 0 879774808 2658304 295 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 649 295 249 194 0 35 0
[pid=13481] ppid=13454 vsize=29428 CPUtime=1.34
/proc/13481/stat : 13481 (aptsolutions.na) R 13454 13454 4159 34819 4229 4202496 6941 0 0 0 134 0 0 0 25 0 1 0 879775476 30134272 6829 1283457024 134512640 134971616 4289082496 18446744073709551615 134953866 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/13481/statm: 7357 6829 204 113 0 6759 0
Current children cumulated CPU time (s) 6.56
Current children cumulated vsize (KiB) 32024

[startup+8.4109 s]
/proc/loadavg: 0.88 0.97 0.99 2/42 13481
/proc/meminfo: memFree=735796/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2596 CPUtime=5.22
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 722 32394 0 154 0 0 502 20 18 0 1 0 879774808 2658304 295 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 649 295 249 194 0 35 0
[pid=13481] ppid=13454 vsize=37616 CPUtime=1.73
/proc/13481/stat : 13481 (aptsolutions.na) R 13454 13454 4159 34819 4229 4202496 9012 0 0 0 172 1 0 0 25 0 1 0 879775476 38518784 8900 1283457024 134512640 134971616 4289082496 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/13481/statm: 9404 8900 209 113 0 8806 0
Current children cumulated CPU time (s) 6.95
Current children cumulated vsize (KiB) 40212

[startup+8.51094 s]
/proc/loadavg: 0.88 0.97 0.99 2/42 13481
/proc/meminfo: memFree=735796/1048576 swapFree=2076380/2097144
[pid=13454] ppid=13453 vsize=2596 CPUtime=5.22
/proc/13454/stat : 13454 (aptitude-trendy) S 13453 13454 4159 34819 4229 4202496 722 32394 0 154 0 0 502 20 18 0 1 0 879774808 2658304 295 1283457024 134512640 135304128 4288951344 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/13454/statm: 649 295 249 194 0 35 0
[pid=13481] ppid=13454 vsize=42084 CPUtime=1.83
/proc/13481/stat : 13481 (aptsolutions.na) R 13454 13454 4159 34819 4229 4202496 10094 0 0 0 182 1 0 0 25 0 1 0 879775476 43094016 9982 1283457024 134512640 134971616 4289082496 18446744073709551615 134839976 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/13481/statm: 10521 9982 209 113 0 9923 0
Current children cumulated CPU time (s) 7.05
Current children cumulated vsize (KiB) 44680

Child status: 0
Real time (s): 8.59555
CPU time (s): 7.14845
CPU user time (s): 6.92043
CPU system time (s): 0.228014
CPU usage (%): 83.1645
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.92043
system time used= 0.228014
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 45032
page faults= 154
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 148
involuntary context switches= 140

runsolver used 0 second user time and 0 second system time

The end