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/201108300820/aspcud-1.5/rand992.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand992.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/rand992.cudf.dudf-random.result +sum(installedsize) 

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.02 1.03 1.00 3/34 11994
/proc/meminfo: memFree=916996/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2588 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) R 11992 11993 2160 34817 2160 4202496 366 0 0 0 0 0 0 0 25 0 1 0 56032742 2650112 280 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/11993/statm: 647 280 234 194 0 34 0
[pid=11994] ppid=11993 vsize=2588 CPUtime=0
/proc/11994/stat : 11994 (aspcud-1.5) R 11993 11993 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 56032742 2650112 46 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/11994/statm: 647 46 0 194 0 34 0

[startup+0.138711 s]
/proc/loadavg: 1.02 1.03 1.00 3/34 11994
/proc/meminfo: memFree=916996/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.206734 s]
/proc/loadavg: 1.02 1.03 1.00 3/34 11994
/proc/meminfo: memFree=916996/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.315113 s]
/proc/loadavg: 1.02 1.03 1.00 3/34 11994
/proc/meminfo: memFree=916996/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706727 s]
/proc/loadavg: 1.02 1.03 1.00 3/34 11994
/proc/meminfo: memFree=916996/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50278 s]
/proc/loadavg: 1.02 1.03 1.00 2/37 12004
/proc/meminfo: memFree=886528/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=1924 CPUtime=0
/proc/12002/stat : 12002 (clasp) S 11993 11993 2160 34817 2160 4202496 273 0 18 0 0 0 0 0 23 0 1 0 56032743 1970176 159 1283457024 134512640 136285277 4292574960 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12002/statm: 481 159 144 433 0 46 0
[pid=12003] ppid=11993 vsize=2584 CPUtime=0
/proc/12003/stat : 12003 (gringo) S 11993 11993 2160 34817 2160 4202496 379 0 24 0 0 0 0 0 23 0 1 0 56032743 2646016 271 1283457024 134512640 136933539 4287708736 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12003/statm: 646 271 242 592 0 51 0
[pid=12004] ppid=11993 vsize=27480 CPUtime=1.05
/proc/12004/stat : 12004 (cudf2lp) R 11993 11993 2160 34817 2160 4202496 7494 0 15 0 103 2 0 0 25 0 1 0 56032743 28139520 6008 1283457024 134512640 135786343 4293808368 18446744073709551615 134595923 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12004/statm: 6870 6008 128 311 0 6557 0
Current children cumulated CPU time (s) 1.05
Current children cumulated vsize (KiB) 34584

[startup+3.1116 s]
/proc/loadavg: 1.02 1.03 1.00 2/37 12004
/proc/meminfo: memFree=858928/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=9016 CPUtime=0.02
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 2242 0 20 0 2 0 0 0 18 0 1 0 56032743 9232384 1926 1283457024 134512640 136285277 4292574960 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 2254 1926 177 433 0 1819 0
[pid=12003] ppid=11993 vsize=12304 CPUtime=0.38
/proc/12003/stat : 12003 (gringo) R 11993 11993 2160 34817 2160 4202496 3375 0 24 0 38 0 0 0 18 0 1 0 56032743 12599296 2347 1283457024 134512640 136933539 4287708736 18446744073709551615 136006208 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12003/statm: 3076 2347 242 592 0 2481 0
[pid=12004] ppid=11993 vsize=43696 CPUtime=2.06
/proc/12004/stat : 12004 (cudf2lp) R 11993 11993 2160 34817 2160 4202496 13487 0 15 0 203 3 0 0 25 0 1 0 56032743 44744704 10731 1283457024 134512640 135786343 4293808368 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12004/statm: 10924 10731 139 311 0 10611 0
Current children cumulated CPU time (s) 2.46
Current children cumulated vsize (KiB) 67612
heavy processes:

[startup+6.31297 s]
/proc/loadavg: 1.01 1.03 1.00 3/37 12004
/proc/meminfo: memFree=756980/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=0
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 579 1524 0 0 0 0 0 0 25 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=51068 CPUtime=0.28
/proc/12002/stat : 12002 (clasp) S 11993 11993 2160 34817 2160 4202496 14985 0 20 0 24 4 0 0 18 0 1 0 56032743 52293632 12191 1283457024 134512640 136285277 4292574960 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12002/statm: 12767 12191 177 433 0 12332 0
[pid=12003] ppid=11993 vsize=72516 CPUtime=2.65
/proc/12003/stat : 12003 (gringo) S 11993 11993 2160 34817 2160 4202496 24522 0 24 0 258 7 0 0 18 0 1 0 56032743 74256384 14516 1283457024 134512640 136933539 4287708736 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12003/statm: 18129 14516 242 592 0 17534 0
[pid=12004] ppid=11993 vsize=43308 CPUtime=2.72
/proc/12004/stat : 12004 (cudf2lp) R 11993 11993 2160 34817 2160 4202496 13487 0 15 0 268 4 0 0 25 0 1 0 56032743 44347392 10634 1283457024 134512640 135786343 4293808368 18446744073709551615 135191376 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12004/statm: 10827 10634 139 311 0 10514 0
Current children cumulated CPU time (s) 5.65
Current children cumulated vsize (KiB) 169488

[startup+12.7048 s]
/proc/loadavg: 1.09 1.04 1.01 2/36 12004
/proc/meminfo: memFree=656060/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=157196 CPUtime=1.89
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 46124 0 20 0 174 15 0 0 18 0 1 0 56032743 160968704 38075 1283457024 134512640 136285277 4292574960 18446744073709551615 134781549 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 39299 38075 189 433 0 38864 0
Current children cumulated CPU time (s) 12.04
Current children cumulated vsize (KiB) 159792

[startup+25.5078 s]
/proc/loadavg: 1.07 1.04 1.00 2/35 12004
/proc/meminfo: memFree=599968/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=287620 CPUtime=14.68
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 86074 0 21 0 1444 24 0 0 25 0 1 0 56032743 294522880 71638 1283457024 134512640 136285277 4292574960 18446744073709551615 134723310 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 71905 71638 234 433 0 71470 0
Current children cumulated CPU time (s) 24.83
Current children cumulated vsize (KiB) 290216

[startup+51.1138 s]
/proc/loadavg: 1.05 1.04 1.00 2/35 12004
/proc/meminfo: memFree=29072/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=869116 CPUtime=40.22
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 231414 0 21 0 3957 65 0 0 25 0 1 0 56032743 889974784 216978 1283457024 134512640 136285277 4292574960 18446744073709551615 134955205 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 217279 216978 234 433 0 216844 0
Current children cumulated CPU time (s) 50.37
Current children cumulated vsize (KiB) 871712

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

[startup+51.2038 s]
/proc/loadavg: 1.05 1.04 1.00 2/35 12004
/proc/meminfo: memFree=29072/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=871504 CPUtime=40.31
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 232024 0 21 0 3965 66 0 0 25 0 1 0 56032743 892420096 217588 1283457024 134512640 136285277 4292574960 18446744073709551615 134966750 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 217876 217588 234 433 0 217441 0
Current children cumulated CPU time (s) 50.46
Current children cumulated vsize (KiB) 874100

[startup+54.4144 s]
/proc/loadavg: 1.04 1.04 1.00 2/35 12004
/proc/meminfo: memFree=4796/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=931088 CPUtime=43.49
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 246933 0 21 0 4279 70 0 0 25 0 1 0 56032743 953434112 232497 1283457024 134512640 136285277 4292574960 18446744073709551615 134623824 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 232772 232497 234 433 0 232337 0
Current children cumulated CPU time (s) 53.64
Current children cumulated vsize (KiB) 933684

[startup+56.0148 s]
/proc/loadavg: 1.04 1.04 1.00 2/35 12004
/proc/meminfo: memFree=6356/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 299 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 299 251 194 0 36 0
[pid=12002] ppid=11993 vsize=949700 CPUtime=45.09
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 251587 0 21 0 4437 72 0 0 25 0 1 0 56032743 972492800 237151 1283457024 134512640 136285277 4292574960 18446744073709551615 134650508 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 237425 237151 234 433 0 236990 0
Current children cumulated CPU time (s) 55.24
Current children cumulated vsize (KiB) 952296

[startup+57.6123 s]
/proc/loadavg: 1.04 1.04 1.00 2/35 12004
/proc/meminfo: memFree=4260/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 254 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 254 206 194 0 36 0
[pid=12002] ppid=11993 vsize=981420 CPUtime=46.67
/proc/12002/stat : 12002 (clasp) R 11993 11993 2160 34817 2160 4202496 259493 0 21 0 4592 75 0 0 25 0 1 0 56032743 1004974080 245057 1283457024 134512640 136285277 4292574960 18446744073709551615 134951781 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12002/statm: 245355 245057 234 433 0 244920 0
Current children cumulated CPU time (s) 56.82
Current children cumulated vsize (KiB) 984016

[startup+58.0064 s]
/proc/loadavg: 1.04 1.04 1.00 2/35 12004
/proc/meminfo: memFree=4260/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=10.15
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 580 95588 0 39 0 0 978 37 18 0 1 0 56032742 2658304 80 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 80 32 194 0 36 0
[pid=12002] ppid=11993 vsize=984544 CPUtime=47.02
/proc/12002/stat : 12002 (clasp) D 11993 11993 2160 34817 2160 4204544 260290 0 21 0 4616 86 0 0 25 0 1 0 56032743 1008173056 245621 1283457024 134512640 136285277 4292574960 18446744073709551615 134628497 0 0 6 18944 18446744071564410721 0 0 17 0 0 0 0
/proc/12002/statm: 246136 245621 1 433 0 245701 0
Current children cumulated CPU time (s) 57.17
Current children cumulated vsize (KiB) 987140

[startup+58.5064 s]
/proc/loadavg: 1.12 1.05 1.01 1/36 12006
/proc/meminfo: memFree=985436/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=57.24
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 710 355879 20 60 0 0 5595 129 18 0 1 0 56032742 2658304 212 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 212 164 194 0 36 0
[pid=12006] ppid=11993 vsize=184 CPUtime=0
/proc/12006/stat : 12006 (touch) D 11993 11993 2160 34817 2160 4194304 87 0 1 0 0 0 0 0 19 0 1 0 56038582 188416 27 1283457024 134512640 134554908 4292951760 18446744073709551615 4160282067 0 0 16898 0 18446744071564252162 0 0 17 0 0 0 0
/proc/12006/statm: 46 27 21 11 0 5 0
Current children cumulated CPU time (s) 57.24
Current children cumulated vsize (KiB) 2780

[startup+58.6063 s]
/proc/loadavg: 1.12 1.05 1.01 1/36 12006
/proc/meminfo: memFree=985436/1048576 swapFree=0/0
[pid=11993] ppid=11992 vsize=2596 CPUtime=57.24
/proc/11993/stat : 11993 (aspcud-1.5) S 11992 11993 2160 34817 2160 4202496 762 356082 20 65 0 0 5595 129 18 0 1 0 56032742 2658304 223 1283457024 134512640 135304128 4293660896 18446744073709551615 4294960130 0 65536 16902 1132543225 18446744071564329979 0 0 17 0 0 0 0
/proc/11993/statm: 649 223 175 194 0 36 0
Current children cumulated CPU time (s) 57.24
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 58.6699
CPU time (s): 57.2516
CPU user time (s): 55.9515
CPU system time (s): 1.30008
CPU usage (%): 97.5826
Max. virtual memory (cumulated for all children) (KiB): 987140

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 55.9515
system time used= 1.30008
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 359204
page faults= 91
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 13311
involuntary context switches= 12220

runsolver used 0.004 second user time and 0 second system time

The end