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/2f690324-4939-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/debian-dudf//2f690324-4939-11df-9e6e-00163e7a6f5e.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/2f690324-4939-11df-9e6e-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.90 0.99 1.04 4/46 12744
/proc/meminfo: memFree=688136/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 513 1358 0 0 0 0 0 0 18 0 1 0 875410352 2650112 280 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 280 237 194 0 33 0
[pid=12744] ppid=12736 vsize=108 CPUtime=0.01
/proc/12744/stat : 12744 (cp) R 12736 12736 2059 34821 2220 4194304 61 0 0 0 0 1 0 0 25 0 1 0 875410353 110592 2 1283457024 0 0 4291298217 18446744073709551615 4294960130 0 0 0 0 0 0 0 17 0 0 0 0
/proc/12744/statm: 27 2 0 0 0 1 0

[startup+0.158763 s]
/proc/loadavg: 0.90 0.99 1.04 4/46 12744
/proc/meminfo: memFree=688136/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) R 12735 12736 2059 34821 2220 4202496 542 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+0.208767 s]
/proc/loadavg: 0.90 0.99 1.04 4/46 12744
/proc/meminfo: memFree=688136/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 560 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+0.308806 s]
/proc/loadavg: 0.90 0.99 1.04 4/46 12744
/proc/meminfo: memFree=688136/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 560 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+0.708899 s]
/proc/loadavg: 0.90 0.99 1.04 4/46 12744
/proc/meminfo: memFree=688136/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 560 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
Current children cumulated CPU time (s) 0.05
Current children cumulated vsize (KiB) 2588

[startup+1.50907 s]
/proc/loadavg: 0.90 0.99 1.04 2/47 12747
/proc/meminfo: memFree=645716/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 560 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
[pid=12747] ppid=12736 vsize=30776 CPUtime=1.45
/proc/12747/stat : 12747 (cudftodeb.nativ) R 12736 12736 2059 34821 2220 4202496 7266 0 0 0 143 2 0 0 25 0 1 0 875410357 31514624 7193 1283457024 134512640 135004320 4290334176 18446744073709551615 134615763 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12747/statm: 7694 7193 225 121 0 7086 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 33364

[startup+3.10941 s]
/proc/loadavg: 0.90 0.99 1.04 2/47 12747
/proc/meminfo: memFree=625256/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 560 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
[pid=12747] ppid=12736 vsize=59672 CPUtime=3.05
/proc/12747/stat : 12747 (cudftodeb.nativ) R 12736 12736 2059 34821 2220 4202496 14388 0 0 0 302 3 0 0 25 0 1 0 875410357 61104128 14315 1283457024 134512640 135004320 4290334176 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12747/statm: 14918 14315 225 121 0 14310 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 62260

[startup+6.31051 s]
/proc/loadavg: 0.91 0.99 1.04 2/47 12747
/proc/meminfo: memFree=568588/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2588 CPUtime=0.05
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 560 1860 0 0 0 0 0 5 25 0 1 0 875410352 2650112 283 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 647 283 240 194 0 33 0
[pid=12747] ppid=12736 vsize=115216 CPUtime=6.25
/proc/12747/stat : 12747 (cudftodeb.nativ) R 12736 12736 2059 34821 2220 4202496 28002 0 0 0 620 5 0 0 25 0 1 0 875410357 117981184 27929 1283457024 134512640 135004320 4290334176 18446744073709551615 134865202 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12747/statm: 28804 27929 237 121 0 28196 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 117804

[startup+12.7075 s]
/proc/loadavg: 0.91 0.99 1.04 1/47 12758
/proc/meminfo: memFree=569532/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2596 CPUtime=9.72
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 689 40684 0 1 0 0 944 28 18 0 1 0 875410352 2658304 294 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 649 294 249 194 0 35 0
[pid=12757] ppid=12736 vsize=108412 CPUtime=1.25
/proc/12757/stat : 12757 (aptitude) D 12736 12736 2059 34821 2220 4202496 7070 240 362 0 119 6 0 0 18 0 1 0 875411416 111013888 7274 1283457024 134512640 137933492 4290507648 18446744073709551615 4294960130 0 134217728 4096 0 18446744071564332537 0 0 17 0 0 0 0
/proc/12757/statm: 27103 7274 7180 836 0 65 0
Current children cumulated CPU time (s) 10.97
Current children cumulated vsize (KiB) 111008

[startup+25.5113 s]
/proc/loadavg: 0.93 0.99 1.04 2/47 12763
/proc/meminfo: memFree=488040/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2596 CPUtime=18.72
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 714 73586 0 363 0 0 1829 43 18 0 1 0 875410352 2658304 294 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 649 294 249 194 0 35 0
[pid=12763] ppid=12736 vsize=92168 CPUtime=4.63
/proc/12763/stat : 12763 (aptsolutions.na) R 12736 12736 2059 34821 2220 4202496 22372 0 0 0 461 2 0 0 25 0 1 0 875412438 94380032 22258 1283457024 134512640 134971616 4288510960 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12763/statm: 23042 22258 209 113 0 22444 0
Current children cumulated CPU time (s) 23.35
Current children cumulated vsize (KiB) 94764

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

[startup+25.6113 s]
/proc/loadavg: 0.93 0.99 1.04 2/47 12763
/proc/meminfo: memFree=488040/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2596 CPUtime=18.72
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 714 73586 0 363 0 0 1829 43 18 0 1 0 875410352 2658304 294 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 649 294 249 194 0 35 0
[pid=12763] ppid=12736 vsize=94648 CPUtime=4.73
/proc/12763/stat : 12763 (aptsolutions.na) R 12736 12736 2059 34821 2220 4202496 22982 0 0 0 471 2 0 0 25 0 1 0 875412438 96919552 22868 1283457024 134512640 134971616 4288510960 18446744073709551615 134912885 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12763/statm: 23662 22868 209 113 0 23064 0
Current children cumulated CPU time (s) 23.45
Current children cumulated vsize (KiB) 97244

[startup+25.8117 s]
/proc/loadavg: 0.93 0.99 1.04 2/47 12763
/proc/meminfo: memFree=488040/1048576 swapFree=2078884/2097144
[pid=12736] ppid=12735 vsize=2596 CPUtime=18.72
/proc/12736/stat : 12736 (aptitude-parano) S 12735 12736 2059 34821 2220 4202496 714 73586 0 363 0 0 1829 43 18 0 1 0 875410352 2658304 294 1283457024 134512640 135304128 4291419776 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/12736/statm: 649 294 249 194 0 35 0
[pid=12763] ppid=12736 vsize=108896 CPUtime=4.92
/proc/12763/stat : 12763 (aptsolutions.na) R 12736 12736 2059 34821 2220 4202496 25765 0 0 0 490 2 0 0 25 0 1 0 875412438 111509504 25651 1283457024 134512640 134971616 4288510960 18446744073709551615 4294960130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/12763/statm: 27224 25651 209 113 0 26626 0
Current children cumulated CPU time (s) 23.64
Current children cumulated vsize (KiB) 111492

Child status: 0
Real time (s): 25.8221
CPU time (s): 23.6735
CPU user time (s): 23.1974
CPU system time (s): 0.476029
CPU usage (%): 91.6792
Max. virtual memory (cumulated for all children) (KiB): 148804

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.1974
system time used= 0.476029
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 100082
page faults= 363
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 218
involuntary context switches= 398

runsolver used 0 second user time and 0.008 second system time

The end