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/aspcud-paranoid-1.3/rand815.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./aspcud-paranoid-1.3 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand815.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012061533/aspcud-paranoid-1.3/rand815.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.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.55 1.39 1.24 4/46 21484
/proc/meminfo: memFree=624660/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2588 CPUtime=0
/proc/21483/stat : 21483 (aspcud-paranoid) R 21482 21483 2059 34821 2220 4202496 368 0 0 0 0 0 0 0 25 0 1 0 876015209 2650112 282 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/21483/statm: 647 282 237 194 0 33 0
[pid=21484] ppid=21483 vsize=2588 CPUtime=0
/proc/21484/stat : 21484 (aspcud-paranoid) R 21483 21483 2059 34821 2220 4202560 0 0 0 0 0 0 0 0 25 0 1 0 876015209 2650112 45 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/21484/statm: 647 45 0 194 0 33 0

[startup+0.174726 s]
/proc/loadavg: 1.55 1.39 1.24 4/46 21484
/proc/meminfo: memFree=624660/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=0.01
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 665 2928 0 0 0 1 0 0 25 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.204741 s]
/proc/loadavg: 1.55 1.39 1.24 4/46 21484
/proc/meminfo: memFree=624660/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=0.01
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 665 2928 0 0 0 1 0 0 25 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.304743 s]
/proc/loadavg: 1.55 1.39 1.24 4/46 21484
/proc/meminfo: memFree=624660/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=0.01
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 665 2928 0 0 0 1 0 0 25 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+0.704812 s]
/proc/loadavg: 1.55 1.39 1.24 4/46 21484
/proc/meminfo: memFree=624660/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=0.01
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 665 2928 0 0 0 1 0 0 25 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2600

[startup+1.50493 s]
/proc/loadavg: 1.50 1.38 1.24 2/49 21500
/proc/meminfo: memFree=581864/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=0.01
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 665 2928 0 0 0 1 0 0 25 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
[pid=21498] ppid=21483 vsize=5228 CPUtime=0.01
/proc/21498/stat : 21498 (clasp) S 21483 21483 2059 34821 2220 4202496 1150 0 0 0 1 0 0 0 18 0 1 0 876015211 5353472 1018 1283457024 134512640 136223643 4289391760 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/21498/statm: 1307 1018 174 418 0 887 0
[pid=21499] ppid=21483 vsize=7356 CPUtime=0.15
/proc/21499/stat : 21499 (gringo) R 21483 21483 2059 34821 2220 4202496 1773 0 0 0 15 0 0 0 18 0 1 0 876015211 7532544 1270 1283457024 134512640 136959103 4291686208 18446744073709551615 134813312 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21499/statm: 1839 1270 247 598 0 1238 0
[pid=21500] ppid=21483 vsize=45400 CPUtime=1.31
/proc/21500/stat : 21500 (cudf2lp) R 21483 21483 2059 34821 2220 4202496 14557 0 0 0 125 6 0 0 25 0 1 0 876015211 46489600 11145 1283457024 134512640 135749571 4290420256 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0
/proc/21500/statm: 11350 11145 129 302 0 11046 0
Current children cumulated CPU time (s) 1.48
Current children cumulated vsize (KiB) 60584

[startup+3.10521 s]
/proc/loadavg: 1.50 1.38 1.24 3/48 21500
/proc/meminfo: memFree=593784/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=2.79
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 666 30598 0 0 0 1 263 15 18 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
[pid=21498] ppid=21483 vsize=37076 CPUtime=0.3
/proc/21498/stat : 21498 (clasp) R 21483 21483 2059 34821 2220 4202496 9944 0 0 0 27 3 0 0 18 0 1 0 876015211 37965824 8306 1283457024 134512640 136223643 4289391760 18446744073709551615 134769738 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21498/statm: 9269 8306 197 418 0 8849 0
Current children cumulated CPU time (s) 3.09
Current children cumulated vsize (KiB) 39676

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

[startup+3.20524 s]
/proc/loadavg: 1.50 1.38 1.24 3/48 21500
/proc/meminfo: memFree=593784/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=2.79
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 666 30598 0 0 0 1 263 15 18 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
[pid=21498] ppid=21483 vsize=38092 CPUtime=0.4
/proc/21498/stat : 21498 (clasp) R 21483 21483 2059 34821 2220 4202496 10814 0 0 0 37 3 0 0 18 0 1 0 876015211 39006208 8727 1283457024 134512640 136223643 4289391760 18446744073709551615 134882810 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21498/statm: 9523 8727 214 418 0 9103 0
Current children cumulated CPU time (s) 3.19
Current children cumulated vsize (KiB) 40692

[startup+3.6053 s]
/proc/loadavg: 1.50 1.38 1.24 2/47 21500
/proc/meminfo: memFree=589708/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=2.79
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 666 30598 0 0 0 1 263 15 18 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
[pid=21498] ppid=21483 vsize=38092 CPUtime=0.8
/proc/21498/stat : 21498 (clasp) R 21483 21483 2059 34821 2220 4202496 10815 0 0 0 77 3 0 0 18 0 1 0 876015211 39006208 8728 1283457024 134512640 136223643 4289391760 18446744073709551615 134887224 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21498/statm: 9523 8728 214 418 0 9103 0
Current children cumulated CPU time (s) 3.59
Current children cumulated vsize (KiB) 40692

[startup+4.00539 s]
/proc/loadavg: 1.50 1.38 1.24 2/47 21500
/proc/meminfo: memFree=589708/1048576 swapFree=2078744/2097144
[pid=21483] ppid=21482 vsize=2600 CPUtime=2.79
/proc/21483/stat : 21483 (aspcud-paranoid) S 21482 21483 2059 34821 2220 4202496 666 30598 0 0 0 1 263 15 18 0 1 0 876015209 2662400 301 1283457024 134512640 135304128 4294644096 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/21483/statm: 650 301 253 194 0 36 0
[pid=21498] ppid=21483 vsize=37548 CPUtime=1.2
/proc/21498/stat : 21498 (clasp) R 21483 21483 2059 34821 2220 4202496 10839 0 0 0 117 3 0 0 19 0 1 0 876015211 38449152 8626 1283457024 134512640 136223643 4289391760 18446744073709551615 134650794 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/21498/statm: 9387 8626 225 418 0 8967 0
Current children cumulated CPU time (s) 3.99
Current children cumulated vsize (KiB) 40148

Child status: 0
Real time (s): 4.05298
CPU time (s): 4.04825
CPU user time (s): 3.84024
CPU system time (s): 0.208013
CPU usage (%): 99.8833
Max. virtual memory (cumulated for all children) (KiB): 77268

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 3.84024
system time used= 0.208013
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 45714
page faults= 0
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 1476
involuntary context switches= 1061

runsolver used 0 second user time and 0 second system time

The end