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/e8a3eb4c-4c81-11df-8b8c-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/debian-dudf//e8a3eb4c-4c81-11df-8b8c-00163e7a6f5e.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/e8a3eb4c-4c81-11df-8b8c-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: 1.38 1.25 1.23 5/46 908
/proc/meminfo: memFree=725344/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0

[startup+0.272557 s]
/proc/loadavg: 1.38 1.25 1.23 5/46 908
/proc/meminfo: memFree=725344/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+0.312571 s]
/proc/loadavg: 1.38 1.25 1.23 5/46 908
/proc/meminfo: memFree=725344/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+0.412576 s]
/proc/loadavg: 1.38 1.25 1.23 5/46 908
/proc/meminfo: memFree=725344/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+0.712634 s]
/proc/loadavg: 1.38 1.25 1.23 5/46 908
/proc/meminfo: memFree=725344/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+1.51284 s]
/proc/loadavg: 1.38 1.25 1.23 2/47 918
/proc/meminfo: memFree=681568/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
[pid=917] ppid=907 vsize=30524 CPUtime=1.46
/proc/917/stat : 917 (cudftodeb.nativ) R 907 907 2059 34821 2220 4202496 7208 0 0 0 144 2 0 0 25 0 1 0 876694389 31256576 7134 1283457024 134512640 135004320 4292226992 18446744073709551615 134959863 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/917/statm: 7631 7134 225 121 0 7023 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 33112

[startup+3.1131 s]
/proc/loadavg: 1.38 1.25 1.23 2/47 918
/proc/meminfo: memFree=661356/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
[pid=917] ppid=907 vsize=59420 CPUtime=3.05
/proc/917/stat : 917 (cudftodeb.nativ) R 907 907 2059 34821 2220 4202496 14315 0 0 0 302 3 0 0 25 0 1 0 876694389 60846080 14241 1283457024 134512640 135004320 4292226992 18446744073709551615 134607602 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/917/statm: 14855 14241 225 121 0 14247 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 62008

[startup+6.31409 s]
/proc/loadavg: 1.35 1.25 1.23 2/47 918
/proc/meminfo: memFree=605680/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2588 CPUtime=0.05
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 572 1867 0 0 0 0 0 5 25 0 1 0 876694383 2650112 285 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 647 285 240 194 0 33 0
[pid=917] ppid=907 vsize=113724 CPUtime=6.24
/proc/917/stat : 917 (cudftodeb.nativ) R 907 907 2059 34821 2220 4202496 27661 0 0 0 612 12 0 0 25 0 1 0 876694389 116453376 27587 1283457024 134512640 135004320 4292226992 18446744073709551615 134947997 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/917/statm: 28431 27587 237 121 0 27823 0
Current children cumulated CPU time (s) 6.29
Current children cumulated vsize (KiB) 116312

[startup+12.7053 s]
/proc/loadavg: 1.32 1.24 1.23 1/47 929
/proc/meminfo: memFree=607496/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=9.13
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 707 33984 0 1 0 0 884 29 19 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
[pid=928] ppid=907 vsize=108408 CPUtime=1.25
/proc/928/stat : 928 (aptitude) D 907 907 2059 34821 2220 4202496 7085 240 363 0 120 5 0 0 18 0 1 0 876695424 111009792 7288 1283457024 134512640 137933492 4293902000 18446744073709551615 4294960130 0 134217728 4096 0 18446744071564332537 0 0 17 0 0 0 0
/proc/928/statm: 27102 7288 7194 836 0 64 0
Current children cumulated CPU time (s) 10.38
Current children cumulated vsize (KiB) 111004

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

[startup+12.9053 s]
/proc/loadavg: 1.32 1.24 1.23 1/47 929
/proc/meminfo: memFree=607496/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=9.13
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 707 33984 0 1 0 0 884 29 19 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
[pid=928] ppid=907 vsize=108408 CPUtime=1.26
/proc/928/stat : 928 (aptitude) D 907 907 2059 34821 2220 4202496 7085 240 363 0 120 6 0 0 18 0 1 0 876695424 111009792 7288 1283457024 134512640 137933492 4293902000 18446744073709551615 4294960130 0 134217728 4096 0 18446744071564332537 0 0 17 0 0 0 0
/proc/928/statm: 27102 7288 7194 836 0 64 0
Current children cumulated CPU time (s) 10.39
Current children cumulated vsize (KiB) 111004

[startup+19.3106 s]
/proc/loadavg: 1.30 1.24 1.22 2/48 932
/proc/meminfo: memFree=558296/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=16.14
/proc/907/stat : 907 (aptitude-parano) R 906 907 2059 34821 2220 4202496 716 64689 0 364 0 0 1570 44 18 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
Current children cumulated CPU time (s) 16.14
Current children cumulated vsize (KiB) 2596

[startup+22.5113 s]
/proc/loadavg: 1.27 1.23 1.22 2/47 934
/proc/meminfo: memFree=552972/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=16.14
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 733 64689 0 364 0 0 1570 44 18 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
[pid=934] ppid=907 vsize=64092 CPUtime=3.32
/proc/934/stat : 934 (aptsolutions.na) R 907 907 2059 34821 2220 4202496 15507 0 0 0 324 8 0 0 25 0 1 0 876696302 65630208 15392 1283457024 134512640 134971616 4294476192 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/934/statm: 16023 15392 204 113 0 15425 0
Current children cumulated CPU time (s) 19.46
Current children cumulated vsize (KiB) 66688

[startup+23.3116 s]
/proc/loadavg: 1.27 1.23 1.22 2/47 934
/proc/meminfo: memFree=535736/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=16.14
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 733 64689 0 364 0 0 1570 44 18 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
[pid=934] ppid=907 vsize=76252 CPUtime=4.12
/proc/934/stat : 934 (aptsolutions.na) R 907 907 2059 34821 2220 4202496 18436 0 0 0 401 11 0 0 25 0 1 0 876696302 78082048 18321 1283457024 134512640 134971616 4294476192 18446744073709551615 134911431 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/934/statm: 19063 18321 204 113 0 18465 0
Current children cumulated CPU time (s) 20.26
Current children cumulated vsize (KiB) 78848

[startup+23.7116 s]
/proc/loadavg: 1.27 1.23 1.22 2/47 934
/proc/meminfo: memFree=535736/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=16.14
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 733 64689 0 364 0 0 1570 44 18 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
[pid=934] ppid=907 vsize=84948 CPUtime=4.52
/proc/934/stat : 934 (aptsolutions.na) R 907 907 2059 34821 2220 4202496 20541 0 0 0 440 12 0 0 25 0 1 0 876696302 86986752 20426 1283457024 134512640 134971616 4294476192 18446744073709551615 134922114 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/934/statm: 21237 20426 208 113 0 20639 0
Current children cumulated CPU time (s) 20.66
Current children cumulated vsize (KiB) 87544

[startup+24.1117 s]
/proc/loadavg: 1.27 1.23 1.22 2/47 934
/proc/meminfo: memFree=535736/1048576 swapFree=2078696/2097144
[pid=907] ppid=906 vsize=2596 CPUtime=16.14
/proc/907/stat : 907 (aptitude-parano) S 906 907 2059 34821 2220 4202496 733 64689 0 364 0 0 1570 44 18 0 1 0 876694383 2658304 296 1283457024 134512640 135304128 4290856432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/907/statm: 649 296 249 194 0 35 0
[pid=934] ppid=907 vsize=104436 CPUtime=4.92
/proc/934/stat : 934 (aptsolutions.na) R 907 907 2059 34821 2220 4202496 24939 0 0 0 480 12 0 0 25 0 1 0 876696302 106942464 24824 1283457024 134512640 134971616 4294476192 18446744073709551615 134907884 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/934/statm: 26109 24824 209 113 0 25511 0
Current children cumulated CPU time (s) 21.06
Current children cumulated vsize (KiB) 107032

Child status: 0
Real time (s): 24.1902
CPU time (s): 21.1453
CPU user time (s): 20.5653
CPU system time (s): 0.580036
CPU usage (%): 87.4126
Max. virtual memory (cumulated for all children) (KiB): 116808

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 20.5653
system time used= 0.580036
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 91511
page faults= 364
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 237
involuntary context switches= 386

runsolver used 0 second user time and 0.008 second system time

The end