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/rand753.sarge-etch-lenny.cudf.sarge-etch-lenny.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge-etch-lenny/rand753.sarge-etch-lenny.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand753.sarge-etch-lenny.cudf.sarge-etch-lenny.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.34 1.18 1.11 3/45 19400
/proc/meminfo: memFree=764800/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=5256 CPUtime=0.11
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 974 0 0 0 11 0 0 0 25 0 1 0 875922145 5382144 901 1283457024 134512640 135004320 4288668768 18446744073709551615 134986420 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 1314 901 225 121 0 706 0

[startup+0.313278 s]
/proc/loadavg: 1.34 1.18 1.11 3/45 19400
/proc/meminfo: memFree=764800/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=8728 CPUtime=0.28
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 1846 0 0 0 28 0 0 0 25 0 1 0 875922145 8937472 1773 1283457024 134512640 135004320 4288668768 18446744073709551615 134977504 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 2182 1773 225 121 0 1574 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 11312

[startup+0.413291 s]
/proc/loadavg: 1.34 1.18 1.11 3/45 19400
/proc/meminfo: memFree=764800/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=10712 CPUtime=0.38
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 2347 0 0 0 38 0 0 0 25 0 1 0 875922145 10969088 2274 1283457024 134512640 135004320 4288668768 18446744073709551615 134986146 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 2678 2274 225 121 0 2070 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 13296

[startup+0.513299 s]
/proc/loadavg: 1.34 1.18 1.11 3/45 19400
/proc/meminfo: memFree=764800/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=13104 CPUtime=0.48
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 2908 0 0 0 48 0 0 0 25 0 1 0 875922145 13418496 2835 1283457024 134512640 135004320 4288668768 18446744073709551615 134995972 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 3276 2835 225 121 0 2668 0
Current children cumulated CPU time (s) 0.5
Current children cumulated vsize (KiB) 15688

[startup+0.71333 s]
/proc/loadavg: 1.34 1.18 1.11 3/45 19400
/proc/meminfo: memFree=764800/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=17320 CPUtime=0.67
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 3945 0 0 0 66 1 0 0 25 0 1 0 875922145 17735680 3872 1283457024 134512640 135004320 4288668768 18446744073709551615 134809550 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 4330 3872 225 121 0 3722 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 19904

[startup+1.51344 s]
/proc/loadavg: 1.31 1.17 1.11 2/47 19411
/proc/meminfo: memFree=725716/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=32944 CPUtime=1.48
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 7777 0 0 0 144 4 0 0 25 0 1 0 875922145 33734656 7704 1283457024 134512640 135004320 4288668768 18446744073709551615 134959967 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 8236 7704 225 121 0 7628 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 35528

[startup+3.11372 s]
/proc/loadavg: 1.31 1.17 1.11 2/47 19411
/proc/meminfo: memFree=701412/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2584 CPUtime=0.02
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 568 1858 0 0 0 0 0 2 25 0 1 0 875922141 2646016 283 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 646 283 240 194 0 32 0
[pid=19410] ppid=19400 vsize=67872 CPUtime=3.08
/proc/19410/stat : 19410 (cudftodeb.nativ) R 19400 19400 2059 34821 2220 4202496 16436 0 0 0 301 7 0 0 25 0 1 0 875922145 69500928 16361 1283457024 134512640 135004320 4288668768 18446744073709551615 134996526 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19410/statm: 16968 16361 237 121 0 16360 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 70456

[startup+6.3056 s]
/proc/loadavg: 1.31 1.17 1.11 1/47 19419
/proc/meminfo: memFree=719148/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=5.62
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 699 26834 0 1 0 0 540 22 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
Current children cumulated CPU time (s) 5.62
Current children cumulated vsize (KiB) 2592

[startup+12.713 s]
/proc/loadavg: 1.42 1.20 1.12 2/48 19425
/proc/meminfo: memFree=639228/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=5.62
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 699 26834 0 1 0 0 540 22 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
[pid=19421] ppid=19400 vsize=93048 CPUtime=5.59
/proc/19421/stat : 19421 (aptitude) S 19400 19400 2059 34821 2220 4202496 23346 652 265 0 543 16 0 0 17 0 2 0 875922767 95281152 17257 1283457024 134512640 137933492 4288901264 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/19421/statm: 23262 17257 5664 836 0 15944 0
[pid=19421/tid=19423] ppid=19400 vsize=93048 CPUtime=2.97
/proc/19421/task/19423/stat : 19423 (aptitude) R 19400 19400 2059 34821 2220 4202560 9445 652 0 0 293 4 0 0 19 0 2 0 875922976 95281152 17257 1283457024 134512640 137933492 4288901264 18446744073709551615 136465865 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.21
Current children cumulated vsize (KiB) 95640

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

[startup+13.0133 s]
/proc/loadavg: 1.42 1.20 1.12 2/48 19425
/proc/meminfo: memFree=639228/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=5.62
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 699 26834 0 1 0 0 540 22 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
[pid=19421] ppid=19400 vsize=94264 CPUtime=5.89
/proc/19421/stat : 19421 (aptitude) R 19400 19400 2059 34821 2220 4202496 23745 652 265 0 573 16 0 0 15 0 2 0 875922767 96526336 17652 1283457024 134512640 137933492 4288901264 18446744073709551615 4153597044 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/19421/statm: 23566 17652 5706 836 0 16241 0
[pid=19421/tid=19423] ppid=19400 vsize=94264 CPUtime=3.19
/proc/19421/task/19423/stat : 19423 (aptitude) R 19400 19400 2059 34821 2220 4202560 9769 652 0 0 315 4 0 0 20 0 2 0 875922976 96526336 17652 1283457024 134512640 137933492 4288901264 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 11.51
Current children cumulated vsize (KiB) 96856

[startup+14.6136 s]
/proc/loadavg: 1.42 1.20 1.12 2/47 19427
/proc/meminfo: memFree=662424/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=12.07
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 725 53331 0 266 0 0 1166 41 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
[pid=19427] ppid=19400 vsize=23968 CPUtime=1.04
/proc/19427/stat : 19427 (aptsolutions.na) R 19400 19400 2059 34821 2220 4202496 5634 0 0 0 102 2 0 0 22 0 1 0 875923499 24543232 5520 1283457024 134512640 134971616 4291841856 18446744073709551615 134623825 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19427/statm: 5992 5520 204 113 0 5394 0
Current children cumulated CPU time (s) 13.11
Current children cumulated vsize (KiB) 26560

[startup+15.4138 s]
/proc/loadavg: 1.42 1.20 1.12 2/47 19427
/proc/meminfo: memFree=662424/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=12.07
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 725 53331 0 266 0 0 1166 41 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
[pid=19427] ppid=19400 vsize=40532 CPUtime=1.83
/proc/19427/stat : 19427 (aptsolutions.na) R 19400 19400 2059 34821 2220 4202496 9705 0 0 0 180 3 0 0 25 0 1 0 875923499 41504768 9589 1283457024 134512640 134971616 4291841856 18446744073709551615 134913947 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19427/statm: 10133 9589 204 113 0 9535 0
Current children cumulated CPU time (s) 13.9
Current children cumulated vsize (KiB) 43124

[startup+15.8039 s]
/proc/loadavg: 1.42 1.20 1.12 2/47 19427
/proc/meminfo: memFree=641592/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=12.07
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 725 53331 0 266 0 0 1166 41 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
[pid=19427] ppid=19400 vsize=47476 CPUtime=2.22
/proc/19427/stat : 19427 (aptsolutions.na) R 19400 19400 2059 34821 2220 4202496 11397 0 0 0 219 3 0 0 25 0 1 0 875923499 48615424 11281 1283457024 134512640 134971616 4291841856 18446744073709551615 134954131 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19427/statm: 11869 11281 204 113 0 11271 0
Current children cumulated CPU time (s) 14.29
Current children cumulated vsize (KiB) 50068

[startup+16.004 s]
/proc/loadavg: 1.42 1.20 1.12 2/47 19427
/proc/meminfo: memFree=641592/1048576 swapFree=2078744/2097144
[pid=19400] ppid=19399 vsize=2592 CPUtime=12.07
/proc/19400/stat : 19400 (aptitude-parano) S 19399 19400 2059 34821 2220 4202496 725 53331 0 266 0 0 1166 41 18 0 1 0 875922141 2654208 294 1283457024 134512640 135304128 4294115616 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/19400/statm: 648 294 249 194 0 34 0
[pid=19427] ppid=19400 vsize=57532 CPUtime=2.42
/proc/19427/stat : 19427 (aptsolutions.na) R 19400 19400 2059 34821 2220 4202496 13712 0 0 0 239 3 0 0 25 0 1 0 875923499 58912768 13596 1283457024 134512640 134971616 4291841856 18446744073709551615 134907909 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/19427/statm: 14383 13596 209 113 0 13785 0
Current children cumulated CPU time (s) 14.49
Current children cumulated vsize (KiB) 60124

Child status: 0
Real time (s): 16.013
CPU time (s): 14.5089
CPU user time (s): 14.0609
CPU system time (s): 0.448028
CPU usage (%): 90.6072
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 14.0609
system time used= 0.448028
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 67897
page faults= 266
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 244
involuntary context switches= 374

runsolver used 0.004 second user time and 0.004 second system time

The end