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/rand494.sarge-etch.cudf.sarge-etch.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge-etch/rand494.sarge-etch.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand494.sarge-etch.cudf.sarge-etch.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.08 1.16 1.11 5/45 14541
/proc/meminfo: memFree=838184/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2548 CPUtime=0
/proc/14541/stat : 14541 (aptitude-parano) R 14540 14541 2059 34821 2220 4202496 292 0 0 0 0 0 0 0 25 0 1 0 875552614 2609152 207 1283457024 134512640 135304128 4287408848 18446744073709551615 135195273 0 0 4 0 0 0 0 17 0 0 0 0
/proc/14541/statm: 637 207 174 194 0 23 0

[startup+0.125238 s]
/proc/loadavg: 1.08 1.16 1.11 5/45 14541
/proc/meminfo: memFree=838184/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2584 CPUtime=0.02
/proc/14541/stat : 14541 (aptitude-parano) R 14540 14541 2059 34821 2220 4202496 551 1858 0 0 0 0 0 2 25 0 1 0 875552614 2646016 284 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/14541/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.213286 s]
/proc/loadavg: 1.08 1.16 1.11 5/45 14541
/proc/meminfo: memFree=838184/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2584 CPUtime=0.02
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 569 1858 0 0 0 0 0 2 25 0 1 0 875552614 2646016 284 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.31332 s]
/proc/loadavg: 1.08 1.16 1.11 5/45 14541
/proc/meminfo: memFree=838184/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2584 CPUtime=0.02
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 569 1858 0 0 0 0 0 2 25 0 1 0 875552614 2646016 284 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+0.7134 s]
/proc/loadavg: 1.08 1.16 1.11 5/45 14541
/proc/meminfo: memFree=838184/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2584 CPUtime=0.02
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 569 1858 0 0 0 0 0 2 25 0 1 0 875552614 2646016 284 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 646 284 240 194 0 32 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2584

[startup+1.51354 s]
/proc/loadavg: 1.08 1.16 1.11 2/47 14552
/proc/meminfo: memFree=808976/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2584 CPUtime=0.02
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 569 1858 0 0 0 0 0 2 25 0 1 0 875552614 2646016 284 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 646 284 240 194 0 32 0
[pid=14552] ppid=14541 vsize=33932 CPUtime=1.47
/proc/14552/stat : 14552 (cudftodeb.nativ) R 14541 14541 2059 34821 2220 4202496 8083 0 0 0 142 5 0 0 25 0 1 0 875552618 34746368 8010 1283457024 134512640 135004320 4290180560 18446744073709551615 134996501 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14552/statm: 8483 8010 236 121 0 7875 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 36516

[startup+3.11384 s]
/proc/loadavg: 1.08 1.16 1.11 2/47 14552
/proc/meminfo: memFree=783432/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2584 CPUtime=0.02
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 569 1858 0 0 0 0 0 2 25 0 1 0 875552614 2646016 284 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 646 284 240 194 0 32 0
[pid=14552] ppid=14541 vsize=30244 CPUtime=3.07
/proc/14552/stat : 14552 (cudftodeb.nativ) R 14541 14541 2059 34821 2220 4202496 12435 0 0 0 296 11 0 0 25 0 1 0 875552618 30969856 7116 1283457024 134512640 135004320 4290180560 18446744073709551615 134996520 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14552/statm: 7561 7116 237 121 0 6953 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 32828

[startup+6.31649 s]
/proc/loadavg: 1.08 1.16 1.11 2/48 14565
/proc/meminfo: memFree=779176/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2592 CPUtime=3.3
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 702 17464 0 1 0 0 313 17 18 0 1 0 875552614 2654208 295 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 648 295 249 194 0 34 0
[pid=14562] ppid=14541 vsize=49504 CPUtime=1.65
/proc/14562/stat : 14562 (aptitude) R 14541 14541 2059 34821 2220 4202496 10647 651 167 0 160 5 0 0 20 0 2 0 875553024 50692096 6717 1283457024 134512640 137933492 4290322960 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/14562/statm: 12376 6717 4022 836 0 6785 0
[pid=14562/tid=14564] ppid=14541 vsize=49504 CPUtime=0.08
/proc/14562/task/14564/stat : 14564 (aptitude) R 14541 14541 2059 34821 2220 4202560 1077 651 0 0 8 0 0 0 15 0 2 0 875553153 50692096 6717 1283457024 134512640 137933492 4290322960 18446744073709551615 4153904414 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.95
Current children cumulated vsize (KiB) 52096
heavy processes:

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

[startup+6.40652 s]
/proc/loadavg: 1.07 1.16 1.11 3/48 14566
/proc/meminfo: memFree=776448/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2592 CPUtime=3.3
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 702 17464 0 1 0 0 313 17 18 0 1 0 875552614 2654208 295 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 648 295 249 194 0 34 0
[pid=14562] ppid=14541 vsize=50824 CPUtime=1.75
/proc/14562/stat : 14562 (aptitude) R 14541 14541 2059 34821 2220 4202496 10981 651 167 0 170 5 0 0 20 0 2 0 875553024 52043776 7051 1283457024 134512640 137933492 4290322960 18446744073709551615 4294960130 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/14562/statm: 12706 7051 4023 836 0 7115 0
[pid=14562/tid=14564] ppid=14541 vsize=50824 CPUtime=0.17
/proc/14562/task/14564/stat : 14564 (aptitude) R 14541 14541 2059 34821 2220 4202560 1411 651 0 0 17 0 0 0 16 0 2 0 875553153 52043776 7051 1283457024 134512640 137933492 4290322960 18446744073709551615 4156089155 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 5.05
Current children cumulated vsize (KiB) 53416

[startup+9.61714 s]
/proc/loadavg: 1.07 1.16 1.11 2/48 14566
/proc/meminfo: memFree=762312/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2592 CPUtime=3.3
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 702 17464 0 1 0 0 313 17 18 0 1 0 875552614 2654208 295 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 648 295 249 194 0 34 0
[pid=14562] ppid=14541 vsize=66428 CPUtime=4.95
/proc/14562/stat : 14562 (aptitude) R 14541 14541 2059 34821 2220 4202496 14935 651 167 0 490 5 0 0 15 0 2 0 875553024 68022272 11002 1283457024 134512640 137933492 4290322960 18446744073709551615 4153886167 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/14562/statm: 16607 11002 4073 836 0 11009 0
[pid=14562/tid=14564] ppid=14541 vsize=66428 CPUtime=3.28
/proc/14562/task/14564/stat : 14564 (aptitude) R 14541 14541 2059 34821 2220 4202560 5198 651 0 0 328 0 0 0 20 0 2 0 875553153 68022272 11002 1283457024 134512640 137933492 4290322960 18446744073709551615 4294960130 0 134217728 4096 0 0 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 8.25
Current children cumulated vsize (KiB) 69020

[startup+10.4072 s]
/proc/loadavg: 1.07 1.16 1.11 3/48 14567
/proc/meminfo: memFree=759336/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2592 CPUtime=8.82
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 728 34826 0 168 0 0 856 26 18 0 1 0 875552614 2654208 295 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 648 295 249 194 0 34 0
Current children cumulated CPU time (s) 8.82
Current children cumulated vsize (KiB) 2592

[startup+11.2074 s]
/proc/loadavg: 1.07 1.16 1.11 2/47 14568
/proc/meminfo: memFree=769636/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2592 CPUtime=8.82
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 728 34826 0 168 0 0 856 26 18 0 1 0 875552614 2654208 295 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 648 295 249 194 0 34 0
[pid=14568] ppid=14541 vsize=23964 CPUtime=1.03
/proc/14568/stat : 14568 (aptsolutions.na) R 14541 14541 2059 34821 2220 4202496 5639 0 0 0 100 3 0 0 21 0 1 0 875553631 24539136 5525 1283457024 134512640 134971616 4293646592 18446744073709551615 134915784 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14568/statm: 5991 5525 204 113 0 5393 0
Current children cumulated CPU time (s) 9.85
Current children cumulated vsize (KiB) 26556

[startup+11.608 s]
/proc/loadavg: 1.07 1.16 1.11 2/47 14568
/proc/meminfo: memFree=769636/1048576 swapFree=2078744/2097144
[pid=14541] ppid=14540 vsize=2592 CPUtime=8.82
/proc/14541/stat : 14541 (aptitude-parano) S 14540 14541 2059 34821 2220 4202496 728 34826 0 168 0 0 856 26 18 0 1 0 875552614 2654208 295 1283457024 134512640 135304128 4287408848 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/14541/statm: 648 295 249 194 0 34 0
[pid=14568] ppid=14541 vsize=0 CPUtime=1.43
/proc/14568/stat : 14568 (aptsolutions.na) R 14541 14541 2059 34821 2220 4202500 8122 0 0 0 139 4 0 0 23 0 1 0 875553631 0 0 1283457024 0 0 0 0 0 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/14568/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 10.25
Current children cumulated vsize (KiB) 2592

Child status: 0
Real time (s): 11.6102
CPU time (s): 10.2686
CPU user time (s): 9.96862
CPU system time (s): 0.300018
CPU usage (%): 88.445
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 9.96862
system time used= 0.300018
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 43693
page faults= 168
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 251
involuntary context switches= 248

runsolver used 0 second user time and 0 second system time

The end