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/randa870aa.cudf.difficult.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/2010/difficult//randa870aa.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/randa870aa.cudf.difficult.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.04 1.17 1.21 4/45 403
/proc/meminfo: memFree=794244/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=3024 CPUtime=0
/proc/403/stat : 403 (runsolver) R 402 403 2059 34821 2220 4202560 72 0 0 0 0 0 0 0 25 0 1 0 876683638 3096576 93 1283457024 134512640 134586868 4294555888 18446744073709551615 134569043 0 0 0 24578 0 0 0 17 0 0 0 0
/proc/403/statm: 756 93 61 19 0 54 0

[startup+0.200353 s]
/proc/loadavg: 1.04 1.17 1.21 4/45 403
/proc/meminfo: memFree=794244/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2588 CPUtime=0.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876683638 2650112 284 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.310381 s]
/proc/loadavg: 1.04 1.17 1.21 4/45 403
/proc/meminfo: memFree=794244/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2588 CPUtime=0.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876683638 2650112 284 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.410406 s]
/proc/loadavg: 1.04 1.17 1.21 4/45 403
/proc/meminfo: memFree=794244/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2588 CPUtime=0.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876683638 2650112 284 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+0.710455 s]
/proc/loadavg: 1.04 1.17 1.21 4/45 403
/proc/meminfo: memFree=794244/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2588 CPUtime=0.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876683638 2650112 284 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.03
Current children cumulated vsize (KiB) 2588

[startup+1.51061 s]
/proc/loadavg: 1.04 1.17 1.21 2/47 414
/proc/meminfo: memFree=756548/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2588 CPUtime=0.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876683638 2650112 284 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 647 284 240 194 0 33 0
[pid=414] ppid=403 vsize=33508 CPUtime=1.47
/proc/414/stat : 414 (cudftodeb.nativ) R 403 403 2059 34821 2220 4202496 7953 0 0 0 144 3 0 0 25 0 1 0 876683641 34312192 7880 1283457024 134512640 135004320 4286730896 18446744073709551615 134606676 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/414/statm: 8377 7880 225 121 0 7769 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 36096

[startup+3.11098 s]
/proc/loadavg: 1.04 1.16 1.21 2/47 414
/proc/meminfo: memFree=734476/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2588 CPUtime=0.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 567 1862 0 0 0 0 0 3 25 0 1 0 876683638 2650112 284 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 647 284 240 194 0 33 0
[pid=414] ppid=403 vsize=68364 CPUtime=3.07
/proc/414/stat : 414 (cudftodeb.nativ) R 403 403 2059 34821 2220 4202496 16503 0 0 0 300 7 0 0 25 0 1 0 876683641 70004736 16430 1283457024 134512640 135004320 4286730896 18446744073709551615 134949298 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/414/statm: 17091 16430 237 121 0 16483 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 70952

[startup+6.30465 s]
/proc/loadavg: 1.04 1.16 1.21 3/47 416
/proc/meminfo: memFree=766960/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=5.6
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 652 25840 0 0 0 0 536 24 18 0 1 0 876683638 2658304 287 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 287 241 194 0 35 0
Current children cumulated CPU time (s) 5.6
Current children cumulated vsize (KiB) 2596

[startup+12.7095 s]
/proc/loadavg: 1.19 1.19 1.21 4/48 428
/proc/meminfo: memFree=687008/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=5.83
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 699 28243 0 1 0 0 556 27 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=424] ppid=403 vsize=70808 CPUtime=5.14
/proc/424/stat : 424 (aptitude) S 403 403 2059 34821 2220 4202496 18432 649 269 0 499 14 0 1 25 0 2 0 876684291 72507392 11968 1283457024 134512640 137933492 4288485264 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/424/statm: 17702 11968 5702 836 0 10341 0
[pid=424/tid=426] ppid=403 vsize=70808 CPUtime=1.83
/proc/424/task/426/stat : 426 (aptitude) R 403 403 2059 34821 2220 4202560 3809 649 1 0 178 4 0 1 18 0 2 0 876684521 72507392 11968 1283457024 134512640 137933492 4288485264 18446744073709551615 134749544 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 10.97
Current children cumulated vsize (KiB) 73404

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

[startup+12.9096 s]
/proc/loadavg: 1.19 1.19 1.21 4/48 428
/proc/meminfo: memFree=687008/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=5.83
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 699 28243 0 1 0 0 556 27 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=424] ppid=403 vsize=71732 CPUtime=5.34
/proc/424/stat : 424 (aptitude) S 403 403 2059 34821 2220 4202496 18656 649 269 0 519 14 0 1 25 0 2 0 876684291 73453568 12192 1283457024 134512640 137933492 4288485264 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/424/statm: 17933 12192 5702 836 0 10572 0
[pid=424/tid=426] ppid=403 vsize=71732 CPUtime=2.03
/proc/424/task/426/stat : 426 (aptitude) R 403 403 2059 34821 2220 4202560 4033 649 1 0 198 4 0 1 18 0 2 0 876684521 73453568 12192 1283457024 134512640 137933492 4288485264 18446744073709551615 136538990 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.17
Current children cumulated vsize (KiB) 74328

[startup+14.51 s]
/proc/loadavg: 1.19 1.19 1.21 3/48 429
/proc/meminfo: memFree=678392/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=5.83
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 699 28243 0 1 0 0 556 27 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=424] ppid=403 vsize=76312 CPUtime=6.94
/proc/424/stat : 424 (aptitude) R 403 403 2059 34821 2220 4202496 21199 1060 269 0 676 16 0 2 17 0 2 0 876684291 78143488 13318 1283457024 134512640 137933492 4288485264 18446744073709551615 4160109171 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/424/statm: 19078 13318 5757 836 0 11710 0
[pid=424/tid=426] ppid=403 vsize=76312 CPUtime=2.95
/proc/424/task/426/stat : 426 (aptitude) R 403 403 2059 34821 2220 4202560 4646 1060 1 0 289 4 0 2 19 0 2 0 876684521 78143488 13318 1283457024 134512640 137933492 4288485264 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 12.77
Current children cumulated vsize (KiB) 78908

[startup+16.1104 s]
/proc/loadavg: 1.19 1.19 1.21 2/47 430
/proc/meminfo: memFree=692784/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=13.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 725 50675 0 270 0 0 1256 47 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=430] ppid=403 vsize=31476 CPUtime=1.33
/proc/430/stat : 430 (aptsolutions.na) R 403 403 2059 34821 2220 4202496 7477 0 0 0 131 2 0 0 22 0 1 0 876685114 32231424 7363 1283457024 134512640 134971616 4293175456 18446744073709551615 134953966 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/430/statm: 7869 7363 204 113 0 7271 0
Current children cumulated CPU time (s) 14.36
Current children cumulated vsize (KiB) 34072

[startup+16.9106 s]
/proc/loadavg: 1.17 1.19 1.21 2/47 430
/proc/meminfo: memFree=669844/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=13.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 725 50675 0 270 0 0 1256 47 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=430] ppid=403 vsize=47476 CPUtime=2.13
/proc/430/stat : 430 (aptsolutions.na) R 403 403 2059 34821 2220 4202496 11345 0 0 0 210 3 0 0 25 0 1 0 876685114 48615424 11231 1283457024 134512640 134971616 4293175456 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/430/statm: 11869 11231 204 113 0 11271 0
Current children cumulated CPU time (s) 15.16
Current children cumulated vsize (KiB) 50072

[startup+17.1106 s]
/proc/loadavg: 1.17 1.19 1.21 2/47 430
/proc/meminfo: memFree=669844/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=13.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 725 50675 0 270 0 0 1256 47 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=430] ppid=403 vsize=51444 CPUtime=2.33
/proc/430/stat : 430 (aptsolutions.na) R 403 403 2059 34821 2220 4202496 12393 0 0 0 230 3 0 0 25 0 1 0 876685114 52678656 12279 1283457024 134512640 134971616 4293175456 18446744073709551615 4158936625 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/430/statm: 12861 12279 204 113 0 12263 0
Current children cumulated CPU time (s) 15.36
Current children cumulated vsize (KiB) 54040

[startup+17.2107 s]
/proc/loadavg: 1.17 1.19 1.21 2/47 430
/proc/meminfo: memFree=669844/1048576 swapFree=2078680/2097144
[pid=403] ppid=402 vsize=2596 CPUtime=13.03
/proc/403/stat : 403 (aptitude-parano) S 402 403 2059 34821 2220 4202496 725 50675 0 270 0 0 1256 47 18 0 1 0 876683638 2658304 295 1283457024 134512640 135304128 4290938432 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/403/statm: 649 295 249 194 0 35 0
[pid=430] ppid=403 vsize=54796 CPUtime=2.43
/proc/430/stat : 430 (aptsolutions.na) R 403 403 2059 34821 2220 4202496 13203 0 0 0 240 3 0 0 25 0 1 0 876685114 56111104 13089 1283457024 134512640 134971616 4293175456 18446744073709551615 134790321 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/430/statm: 13699 13089 208 113 0 13101 0
Current children cumulated CPU time (s) 15.46
Current children cumulated vsize (KiB) 57392

Child status: 0
Real time (s): 17.2682
CPU time (s): 15.533
CPU user time (s): 15.0129
CPU system time (s): 0.520032
CPU usage (%): 89.9514
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 15.0129
system time used= 0.520032
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 65431
page faults= 270
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 325
involuntary context switches= 454

runsolver used 0 second user time and 0.004 second system time

The end