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/rand180.sarge.cudf.sarge.log.runsolver ./aptitude-paranoid-1.0 /home/misc2010/data/icse/sarge/rand180.sarge.cudf /home/misc2010/tmp/201012061533/aptitude-paranoid-1.0/rand180.sarge.cudf.sarge.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.21 1.09 1.08 4/46 9714
/proc/meminfo: memFree=860196/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2580 CPUtime=0.02
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 875114076 2641920 283 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 645 283 240 194 0 31 0
[pid=9714] ppid=9704 vsize=3516 CPUtime=0.03
/proc/9714/stat : 9714 (cudftodeb.nativ) R 9704 9704 2059 34821 2220 4202496 557 0 0 0 3 0 0 0 25 0 1 0 875114078 3600384 484 1283457024 134512640 135004320 4294511104 18446744073709551615 134946100 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9714/statm: 879 484 224 121 0 271 0

[startup+0.154637 s]
/proc/loadavg: 1.21 1.09 1.08 4/46 9714
/proc/meminfo: memFree=860196/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2580 CPUtime=0.02
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 875114076 2641920 283 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 645 283 240 194 0 31 0
[pid=9714] ppid=9704 vsize=5748 CPUtime=0.14
/proc/9714/stat : 9714 (cudftodeb.nativ) R 9704 9704 2059 34821 2220 4202496 1150 0 0 0 14 0 0 0 25 0 1 0 875114078 5885952 1077 1283457024 134512640 135004320 4294511104 18446744073709551615 134613877 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9714/statm: 1437 1077 225 121 0 829 0
Current children cumulated CPU time (s) 0.16
Current children cumulated vsize (KiB) 8328

[startup+0.214647 s]
/proc/loadavg: 1.21 1.09 1.08 4/46 9714
/proc/meminfo: memFree=860196/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2580 CPUtime=0.02
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 875114076 2641920 283 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 645 283 240 194 0 31 0
[pid=9714] ppid=9704 vsize=6988 CPUtime=0.19
/proc/9714/stat : 9714 (cudftodeb.nativ) R 9704 9704 2059 34821 2220 4202496 1455 0 0 0 19 0 0 0 25 0 1 0 875114078 7155712 1382 1283457024 134512640 135004320 4294511104 18446744073709551615 134986252 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9714/statm: 1747 1382 225 121 0 1139 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 9568

[startup+0.31468 s]
/proc/loadavg: 1.21 1.09 1.08 4/46 9714
/proc/meminfo: memFree=860196/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2580 CPUtime=0.02
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 875114076 2641920 283 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 645 283 240 194 0 31 0
[pid=9714] ppid=9704 vsize=9220 CPUtime=0.29
/proc/9714/stat : 9714 (cudftodeb.nativ) R 9704 9704 2059 34821 2220 4202496 1969 0 0 0 28 1 0 0 25 0 1 0 875114078 9441280 1896 1283457024 134512640 135004320 4294511104 18446744073709551615 4294960130 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9714/statm: 2305 1896 225 121 0 1697 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 11800

[startup+0.714773 s]
/proc/loadavg: 1.21 1.09 1.08 4/46 9714
/proc/meminfo: memFree=860196/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2580 CPUtime=0.02
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 565 1857 0 0 0 0 0 2 25 0 1 0 875114076 2641920 283 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 645 283 240 194 0 31 0
[pid=9714] ppid=9704 vsize=18308 CPUtime=0.69
/proc/9714/stat : 9714 (cudftodeb.nativ) R 9704 9704 2059 34821 2220 4202496 4200 0 0 0 67 2 0 0 25 0 1 0 875114078 18747392 4127 1283457024 134512640 135004320 4294511104 18446744073709551615 4160250336 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9714/statm: 4577 4127 236 121 0 3969 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 20888

[startup+1.51502 s]
/proc/loadavg: 1.21 1.09 1.08 2/47 9715
/proc/meminfo: memFree=835336/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2588 CPUtime=1.47
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 648 8995 0 0 0 0 141 6 22 0 1 0 875114076 2650112 286 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 647 286 241 194 0 33 0
Current children cumulated CPU time (s) 1.47
Current children cumulated vsize (KiB) 2588

[startup+3.1097 s]
/proc/loadavg: 1.19 1.09 1.08 2/47 9726
/proc/meminfo: memFree=841100/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2588 CPUtime=1.54
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 694 11396 0 1 0 0 147 7 19 0 1 0 875114076 2650112 294 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 647 294 249 194 0 33 0
[pid=9725] ppid=9704 vsize=38564 CPUtime=0.78
/proc/9725/stat : 9725 (aptitude) R 9704 9704 2059 34821 2220 4202496 6850 1059 82 0 74 4 0 0 22 0 2 0 875114275 39489536 4114 1283457024 134512640 137933492 4289538368 18446744073709551615 4159885383 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/9725/statm: 9641 4114 2655 836 0 5546 0
Current children cumulated CPU time (s) 2.32
Current children cumulated vsize (KiB) 41152
heavy processes:

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

[startup+3.2097 s]
/proc/loadavg: 1.19 1.09 1.08 2/48 9730
/proc/meminfo: memFree=834900/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2588 CPUtime=2.4
/proc/9704/stat : 9704 (aptitude-parano) R 9703 9704 2059 34821 2220 4202496 704 19418 0 83 0 0 227 13 18 0 1 0 875114076 2650112 294 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/9704/statm: 647 294 249 194 0 33 0
Current children cumulated CPU time (s) 2.4
Current children cumulated vsize (KiB) 2588

[startup+3.60983 s]
/proc/loadavg: 1.19 1.09 1.08 2/47 9731
/proc/meminfo: memFree=837520/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2588 CPUtime=2.4
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 720 19418 0 83 0 0 227 13 18 0 1 0 875114076 2650112 294 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 647 294 249 194 0 33 0
[pid=9731] ppid=9704 vsize=12560 CPUtime=0.43
/proc/9731/stat : 9731 (aptsolutions.na) R 9704 9704 2059 34821 2220 4202496 2780 0 0 0 43 0 0 0 21 0 1 0 875114394 12861440 2667 1283457024 134512640 134971616 4292739120 18446744073709551615 134604736 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9731/statm: 3140 2667 204 113 0 2542 0
Current children cumulated CPU time (s) 2.83
Current children cumulated vsize (KiB) 15148

[startup+3.80992 s]
/proc/loadavg: 1.19 1.09 1.08 2/47 9731
/proc/meminfo: memFree=837520/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2588 CPUtime=2.4
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 720 19418 0 83 0 0 227 13 18 0 1 0 875114076 2650112 294 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 647 294 249 194 0 33 0
[pid=9731] ppid=9704 vsize=16776 CPUtime=0.63
/proc/9731/stat : 9731 (aptsolutions.na) R 9704 9704 2059 34821 2220 4202496 3857 0 0 0 62 1 0 0 22 0 1 0 875114394 17178624 3744 1283457024 134512640 134971616 4292739120 18446744073709551615 134917422 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9731/statm: 4194 3744 204 113 0 3596 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 19364

[startup+3.90997 s]
/proc/loadavg: 1.19 1.09 1.08 2/47 9731
/proc/meminfo: memFree=837520/1048576 swapFree=2078740/2097144
[pid=9704] ppid=9703 vsize=2588 CPUtime=2.4
/proc/9704/stat : 9704 (aptitude-parano) S 9703 9704 2059 34821 2220 4202496 720 19418 0 83 0 0 227 13 18 0 1 0 875114076 2650112 294 1283457024 134512640 135304128 4287228608 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9704/statm: 647 294 249 194 0 33 0
[pid=9731] ppid=9704 vsize=21116 CPUtime=0.73
/proc/9731/stat : 9731 (aptsolutions.na) R 9704 9704 2059 34821 2220 4202496 4813 0 0 0 72 1 0 0 22 0 1 0 875114394 21622784 4700 1283457024 134512640 134971616 4292739120 18446744073709551615 134911741 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/9731/statm: 5279 4700 209 113 0 4681 0
Current children cumulated CPU time (s) 3.13
Current children cumulated vsize (KiB) 23704

Child status: 0
Real time (s): 3.94264
CPU time (s): 3.1762
CPU user time (s): 3.02019
CPU system time (s): 0.156009
CPU usage (%): 80.5602
Max. virtual memory (cumulated for all children) (KiB): 111000

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.02019
system time used= 0.156009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 25602
page faults= 83
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 202
involuntary context switches= 163

runsolver used 0 second user time and 0 second system time

The end