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/8ad21cec-4b22-11df-b280-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//8ad21cec-4b22-11df-b280-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/8ad21cec-4b22-11df-b280-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.95 1.01 1.02 1/44 849
/proc/meminfo: memFree=595744/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=3020 CPUtime=0
/proc/849/stat : 849 (runsolver) D 848 849 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 884678991 3092480 93 1283457024 134512640 134586868 4294455424 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/849/statm: 755 93 62 19 0 53 0

[startup+0.167011 s]
/proc/loadavg: 0.95 1.01 1.02 1/44 849
/proc/meminfo: memFree=595744/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.212345 s]
/proc/loadavg: 0.95 1.01 1.02 1/44 849
/proc/meminfo: memFree=595744/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.312374 s]
/proc/loadavg: 0.95 1.01 1.02 1/44 849
/proc/meminfo: memFree=595744/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.712489 s]
/proc/loadavg: 0.95 1.01 1.02 1/44 849
/proc/meminfo: memFree=595744/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+1.51271 s]
/proc/loadavg: 0.95 1.01 1.02 2/46 860
/proc/meminfo: memFree=553360/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
[pid=860] ppid=849 vsize=30460 CPUtime=1.42
/proc/860/stat : 860 (cudftodeb.nativ) R 849 849 4159 34819 4229 4202496 7169 0 8 0 142 0 0 0 25 0 1 0 884678996 31191040 7104 1283457024 134512640 135004320 4287568720 18446744073709551615 134986179 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/860/statm: 7615 7104 225 121 0 7007 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 33044

[startup+3.11317 s]
/proc/loadavg: 0.95 1.01 1.02 2/46 860
/proc/meminfo: memFree=532776/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
[pid=860] ppid=849 vsize=59680 CPUtime=3.03
/proc/860/stat : 860 (cudftodeb.nativ) R 849 849 4159 34819 4229 4202496 14359 0 8 0 299 4 0 0 25 0 1 0 884678996 61112320 14289 1283457024 134512640 135004320 4287568720 18446744073709551615 134527234 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/860/statm: 14920 14289 225 121 0 14312 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 62264

[startup+6.30418 s]
/proc/loadavg: 0.96 1.01 1.02 2/46 860
/proc/meminfo: memFree=476232/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2584 CPUtime=0.04
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 565 1857 0 0 0 0 0 4 25 0 1 0 884678991 2646016 283 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 646 283 240 194 0 32 0
[pid=860] ppid=849 vsize=114980 CPUtime=6.21
/proc/860/stat : 860 (cudftodeb.nativ) R 849 849 4159 34819 4229 4202496 27975 0 8 0 609 12 0 0 25 0 1 0 884678996 117739520 27905 1283457024 134512640 135004320 4287568720 18446744073709551615 134996778 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/860/statm: 28745 27905 237 121 0 28137 0
Current children cumulated CPU time (s) 6.25
Current children cumulated vsize (KiB) 117564

[startup+12.7078 s]
/proc/loadavg: 0.96 1.01 1.02 2/46 871
/proc/meminfo: memFree=471156/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=9.02
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 695 34151 0 9 0 0 874 28 19 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=870] ppid=849 vsize=108408 CPUtime=1.28
/proc/870/stat : 870 (aptitude) D 849 849 4159 34819 4229 4202496 7025 240 428 0 118 10 0 0 18 0 1 0 884679989 111009792 7291 1283457024 134512640 137933492 4291899264 18446744073709551615 4294960130 0 134217728 4096 0 18446744071696460772 0 0 17 0 0 0 0
/proc/870/statm: 27102 7291 7197 836 0 64 0
Current children cumulated CPU time (s) 10.3
Current children cumulated vsize (KiB) 111000

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

[startup+12.8135 s]
/proc/loadavg: 0.96 1.01 1.02 2/46 871
/proc/meminfo: memFree=471156/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=9.02
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 695 34151 0 9 0 0 874 28 19 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=870] ppid=849 vsize=38560 CPUtime=1.36
/proc/870/stat : 870 (aptitude) R 849 849 4159 34819 4229 4202496 13623 240 428 0 124 12 0 0 18 0 1 0 884679989 39485440 7480 1283457024 134512640 137933492 4291899264 18446744073709551615 4159588720 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/870/statm: 9640 7480 6844 836 0 606 0
Current children cumulated CPU time (s) 10.38
Current children cumulated vsize (KiB) 41152

[startup+19.2051 s]
/proc/loadavg: 0.97 1.01 1.02 2/47 874
/proc/meminfo: memFree=419124/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=9.02
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 695 34151 0 9 0 0 874 28 19 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=870] ppid=849 vsize=105124 CPUtime=7.5
/proc/870/stat : 870 (aptitude) S 849 849 4159 34819 4229 4202496 28674 650 438 0 733 17 0 0 15 0 2 0 884679989 107646976 20422 1283457024 134512640 137933492 4291899264 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/870/statm: 26281 20422 7271 836 0 17247 0
[pid=870/tid=872] ppid=849 vsize=105124 CPUtime=3.92
/proc/870/task/872/stat : 872 (aptitude) R 849 849 4159 34819 4229 4202560 10426 650 0 0 392 0 0 0 21 0 2 0 884680330 107646976 20422 1283457024 134512640 137933492 4291899264 18446744073709551615 135914117 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 16.52
Current children cumulated vsize (KiB) 107716

[startup+22.4047 s]
/proc/loadavg: 0.97 1.01 1.02 2/46 876
/proc/meminfo: memFree=437632/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=17.73
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 721 66709 0 448 0 0 1724 49 18 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=876] ppid=849 vsize=39408 CPUtime=1.91
/proc/876/stat : 876 (aptsolutions.na) R 849 849 4159 34819 4229 4202496 9387 0 9 0 186 5 0 0 25 0 1 0 884681035 40353792 9285 1283457024 134512640 134971616 4291673856 18446744073709551615 134914071 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/876/statm: 9852 9285 204 113 0 9254 0
Current children cumulated CPU time (s) 19.64
Current children cumulated vsize (KiB) 42000

[startup+24.0049 s]
/proc/loadavg: 0.97 1.01 1.02 2/46 876
/proc/meminfo: memFree=418660/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=17.73
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 721 66709 0 448 0 0 1724 49 18 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=876] ppid=849 vsize=67808 CPUtime=3.5
/proc/876/stat : 876 (aptsolutions.na) R 849 849 4159 34819 4229 4202496 16406 0 9 0 344 6 0 0 25 0 1 0 884681035 69435392 16304 1283457024 134512640 134971616 4291673856 18446744073709551615 134915762 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/876/statm: 16952 16304 204 113 0 16354 0
Current children cumulated CPU time (s) 21.23
Current children cumulated vsize (KiB) 70400

[startup+24.805 s]
/proc/loadavg: 0.97 1.01 1.02 2/46 876
/proc/meminfo: memFree=400308/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=17.73
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 721 66709 0 448 0 0 1724 49 18 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=876] ppid=849 vsize=80952 CPUtime=4.3
/proc/876/stat : 876 (aptsolutions.na) R 849 849 4159 34819 4229 4202496 19626 0 9 0 422 8 0 0 25 0 1 0 884681035 82894848 19524 1283457024 134512640 134971616 4291673856 18446744073709551615 134628677 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/876/statm: 20238 19524 204 113 0 19640 0
Current children cumulated CPU time (s) 22.03
Current children cumulated vsize (KiB) 83544

[startup+25.2051 s]
/proc/loadavg: 0.97 1.01 1.02 2/46 876
/proc/meminfo: memFree=400308/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=17.73
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 721 66709 0 448 0 0 1724 49 18 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=876] ppid=849 vsize=92404 CPUtime=4.7
/proc/876/stat : 876 (aptsolutions.na) R 849 849 4159 34819 4229 4202496 22480 0 9 0 462 8 0 0 25 0 1 0 884681035 94621696 22378 1283457024 134512640 134971616 4291673856 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/876/statm: 23101 22378 209 113 0 22503 0
Current children cumulated CPU time (s) 22.43
Current children cumulated vsize (KiB) 94996

[startup+25.4052 s]
/proc/loadavg: 0.97 1.01 1.02 2/46 876
/proc/meminfo: memFree=376376/1048576 swapFree=2077616/2097144
[pid=849] ppid=848 vsize=2592 CPUtime=17.73
/proc/849/stat : 849 (aptitude-trendy) S 848 849 4159 34819 4229 4202496 721 66709 0 448 0 0 1724 49 18 0 1 0 884678991 2654208 294 1283457024 134512640 135304128 4286564832 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/849/statm: 648 294 249 194 0 34 0
[pid=876] ppid=849 vsize=102020 CPUtime=4.9
/proc/876/stat : 876 (aptsolutions.na) R 849 849 4159 34819 4229 4202496 24214 0 9 0 480 10 0 0 25 0 1 0 884681035 104468480 24112 1283457024 134512640 134971616 4291673856 18446744073709551615 134912909 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/876/statm: 25505 24112 209 113 0 24907 0
Current children cumulated CPU time (s) 22.63
Current children cumulated vsize (KiB) 104612

Child status: 0
Real time (s): 25.4962
CPU time (s): 22.7414
CPU user time (s): 22.1294
CPU system time (s): 0.612038
CPU usage (%): 89.1955
Max. virtual memory (cumulated for all children) (KiB): 117564

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 22.1294
system time used= 0.612038
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 93271
page faults= 457
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 400
involuntary context switches= 389

runsolver used 0 second user time and 0 second system time

The end