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/58a4a468-38a5-11df-a561-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//58a4a468-38a5-11df-a561-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/58a4a468-38a5-11df-a561-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.01 1.00 1.03 5/45 26701
/proc/meminfo: memFree=754936/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2568 CPUtime=0
/proc/26700/stat : 26700 (aptitude-trendy) R 26699 26700 4159 34819 4229 4202496 357 0 0 0 0 0 0 0 25 0 1 0 883000391 2629632 271 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/26700/statm: 642 271 232 194 0 28 0
[pid=26701] ppid=26700 vsize=2568 CPUtime=0
/proc/26701/stat : 26701 (aptitude-trendy) R 26700 26700 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 883000391 2629632 39 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/26701/statm: 642 39 0 194 0 28 0

[startup+0.200414 s]
/proc/loadavg: 1.01 1.00 1.03 5/45 26701
/proc/meminfo: memFree=754936/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2580

[startup+0.310434 s]
/proc/loadavg: 1.01 1.00 1.03 5/45 26701
/proc/meminfo: memFree=754936/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2580

[startup+0.410464 s]
/proc/loadavg: 1.01 1.00 1.03 5/45 26701
/proc/meminfo: memFree=754936/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2580

[startup+0.710537 s]
/proc/loadavg: 1.01 1.00 1.03 5/45 26701
/proc/meminfo: memFree=754936/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2580

[startup+1.51073 s]
/proc/loadavg: 1.01 1.00 1.03 2/46 26711
/proc/meminfo: memFree=711608/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
[pid=26711] ppid=26700 vsize=30676 CPUtime=1.45
/proc/26711/stat : 26711 (cudftodeb.nativ) R 26700 26700 4159 34819 4229 4202496 7277 0 0 0 139 6 0 0 25 0 1 0 883000396 31412224 7204 1283457024 134512640 135004320 4293452000 18446744073709551615 134828022 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26711/statm: 7669 7204 225 121 0 7061 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 33256

[startup+3.11112 s]
/proc/loadavg: 1.01 1.00 1.03 2/46 26711
/proc/meminfo: memFree=691644/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
[pid=26711] ppid=26700 vsize=58688 CPUtime=3.05
/proc/26711/stat : 26711 (cudftodeb.nativ) R 26700 26700 4159 34819 4229 4202496 14107 0 0 0 297 8 0 0 25 0 1 0 883000396 60096512 14028 1283457024 134512640 135004320 4293452000 18446744073709551615 134961572 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26711/statm: 14672 14028 225 121 0 14064 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 61268

[startup+6.31196 s]
/proc/loadavg: 1.01 1.00 1.03 2/46 26711
/proc/meminfo: memFree=632868/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2580 CPUtime=0.05
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 555 1860 0 0 0 0 0 5 25 0 1 0 883000391 2641920 282 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 645 282 240 194 0 31 0
[pid=26711] ppid=26700 vsize=111992 CPUtime=6.25
/proc/26711/stat : 26711 (cudftodeb.nativ) R 26700 26700 4159 34819 4229 4202496 27298 0 0 0 610 15 0 0 25 0 1 0 883000396 114679808 27219 1283457024 134512640 135004320 4293452000 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26711/statm: 27998 27219 237 121 0 27390 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 114572

[startup+12.7078 s]
/proc/loadavg: 1.01 1.00 1.03 1/46 26722
/proc/meminfo: memFree=637804/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=9.35
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 680 34529 0 1 0 1 902 32 19 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26721] ppid=26700 vsize=38064 CPUtime=1.26
/proc/26721/stat : 26721 (aptitude) R 26700 26700 4159 34819 4229 4202496 7150 241 356 0 114 12 0 0 18 0 1 0 883001428 38977536 1069 1283457024 134512640 137933492 4292017392 18446744073709551615 4153099943 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/26721/statm: 9516 1069 798 836 0 600 0
Current children cumulated CPU time (s) 10.61
Current children cumulated vsize (KiB) 40652

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

[startup+12.9111 s]
/proc/loadavg: 1.01 1.00 1.03 1/46 26722
/proc/meminfo: memFree=637804/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=9.35
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 680 34529 0 1 0 1 902 32 19 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26721] ppid=26700 vsize=38200 CPUtime=1.46
/proc/26721/stat : 26721 (aptitude) R 26700 26700 4159 34819 4229 4202496 13532 241 356 0 133 13 0 0 18 0 1 0 883001428 39116800 7451 1283457024 134512640 137933492 4292017392 18446744073709551615 4159525895 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/26721/statm: 9550 7451 6789 836 0 634 0
Current children cumulated CPU time (s) 10.81
Current children cumulated vsize (KiB) 40788

[startup+16.1118 s]
/proc/loadavg: 1.01 1.00 1.02 3/47 26725
/proc/meminfo: memFree=615476/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=9.35
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 680 34529 0 1 0 1 902 32 19 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26721] ppid=26700 vsize=80452 CPUtime=4.66
/proc/26721/stat : 26721 (aptitude) R 26700 26700 4159 34819 4229 4202496 22479 651 356 0 450 16 0 0 25 0 2 0 883001428 82382848 14299 1283457024 134512640 137933492 4292017392 18446744073709551615 136463302 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/26721/statm: 20113 14299 7195 836 0 11190 0
[pid=26721/tid=26723] ppid=26700 vsize=80452 CPUtime=1.07
/proc/26721/task/26723/stat : 26723 (aptitude) S 26700 26700 4159 34819 4229 4202560 4402 651 0 0 106 1 0 0 17 0 2 0 883001715 82382848 14299 1283457024 134512640 137933492 4292017392 18446744073709551615 4294960130 0 134217728 4096 0 18446612132844133376 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 14.01
Current children cumulated vsize (KiB) 83040

[startup+19.3127 s]
/proc/loadavg: 1.01 1.00 1.02 2/46 26727
/proc/meminfo: memFree=596016/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=14.46
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 705 60007 0 357 0 1 1394 51 18 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26727] ppid=26700 vsize=54924 CPUtime=2.75
/proc/26727/stat : 26727 (aptsolutions.na) R 26700 26700 4159 34819 4229 4202496 13259 0 0 0 271 4 0 0 25 0 1 0 883002046 56242176 13141 1283457024 134512640 134971616 4289942864 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26727/statm: 13731 13141 204 113 0 13133 0
Current children cumulated CPU time (s) 17.21
Current children cumulated vsize (KiB) 57512

[startup+20.1129 s]
/proc/loadavg: 1.01 1.00 1.02 2/46 26727
/proc/meminfo: memFree=577044/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=14.46
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 705 60007 0 357 0 1 1394 51 18 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26727] ppid=26700 vsize=67820 CPUtime=3.55
/proc/26727/stat : 26727 (aptsolutions.na) R 26700 26700 4159 34819 4229 4202496 16445 0 0 0 349 6 0 0 25 0 1 0 883002046 69447680 16327 1283457024 134512640 134971616 4289942864 18446744073709551615 134946844 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26727/statm: 16955 16327 204 113 0 16357 0
Current children cumulated CPU time (s) 18.01
Current children cumulated vsize (KiB) 70408

[startup+20.9131 s]
/proc/loadavg: 1.01 1.00 1.02 2/46 26727
/proc/meminfo: memFree=577044/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=14.46
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 705 60007 0 357 0 1 1394 51 18 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26727] ppid=26700 vsize=80724 CPUtime=4.35
/proc/26727/stat : 26727 (aptsolutions.na) R 26700 26700 4159 34819 4229 4202496 19578 0 0 0 428 7 0 0 25 0 1 0 883002046 82661376 19460 1283457024 134512640 134971616 4289942864 18446744073709551615 134942929 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26727/statm: 20181 19460 208 113 0 19583 0
Current children cumulated CPU time (s) 18.81
Current children cumulated vsize (KiB) 83312

[startup+21.3132 s]
/proc/loadavg: 1.01 1.00 1.02 2/46 26727
/proc/meminfo: memFree=558072/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=14.46
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 705 60007 0 357 0 1 1394 51 18 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26727] ppid=26700 vsize=94392 CPUtime=4.75
/proc/26727/stat : 26727 (aptsolutions.na) R 26700 26700 4159 34819 4229 4202496 22962 0 0 0 466 9 0 0 25 0 1 0 883002046 96657408 22844 1283457024 134512640 134971616 4289942864 18446744073709551615 134824327 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26727/statm: 23598 22844 209 113 0 23000 0
Current children cumulated CPU time (s) 19.21
Current children cumulated vsize (KiB) 96980

[startup+21.4132 s]
/proc/loadavg: 1.01 1.00 1.02 2/46 26727
/proc/meminfo: memFree=558072/1048576 swapFree=2077184/2097144
[pid=26700] ppid=26699 vsize=2588 CPUtime=14.46
/proc/26700/stat : 26700 (aptitude-trendy) S 26699 26700 4159 34819 4229 4202496 705 60007 0 357 0 1 1394 51 18 0 1 0 883000391 2650112 293 1283457024 134512640 135304128 4291153472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/26700/statm: 647 293 249 194 0 33 0
[pid=26727] ppid=26700 vsize=102432 CPUtime=4.85
/proc/26727/stat : 26727 (aptsolutions.na) R 26700 26700 4159 34819 4229 4202496 24455 0 0 0 475 10 0 0 25 0 1 0 883002046 104890368 24337 1283457024 134512640 134971616 4289942864 18446744073709551615 134927985 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/26727/statm: 25608 24337 209 113 0 25010 0
Current children cumulated CPU time (s) 19.31
Current children cumulated vsize (KiB) 105020

Child status: 0
Real time (s): 21.5093
CPU time (s): 19.4252
CPU user time (s): 18.7852
CPU system time (s): 0.64004
CPU usage (%): 90.3106
Max. virtual memory (cumulated for all children) (KiB): 123500

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 18.7852
system time used= 0.64004
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 86619
page faults= 357
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 216
involuntary context switches= 372

runsolver used 0 second user time and 0 second system time

The end