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/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/7c834c0e-51b8-11e0-a49e-00163e1e087d.cudf.dudf-real.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.07 1.09 1.03 4/37 12833
/proc/meminfo: memFree=916932/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2588 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 372 0 0 0 0 0 0 0 25 0 1 0 56499506 2650112 279 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/12831/statm: 647 279 234 194 0 34 0
[pid=12832] ppid=12831 vsize=2588 CPUtime=0
/proc/12832/stat : 12832 (aspcud-1.5) S 12831 12831 2160 34817 2160 4202560 118 0 0 0 0 0 0 0 25 0 1 0 56499506 2650112 133 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/12832/statm: 647 133 87 194 0 34 0
[pid=12833] ppid=12832 vsize=2588 CPUtime=0
/proc/12833/stat : 12833 (aspcud-1.5) R 12832 12831 2160 34817 2160 4202560 126 0 0 0 0 0 0 0 25 0 1 0 56499506 2650112 150 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/12833/statm: 647 150 104 194 0 34 0
[pid=12834] ppid=12833 vsize=2588 CPUtime=0
/proc/12834/stat : 12834 (aspcud-1.5) R 12833 12831 2160 34817 2160 4202560 0 0 0 0 0 0 0 0 25 0 1 0 56499506 2650112 46 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/12834/statm: 647 46 0 194 0 34 0

[startup+0.129351 s]
/proc/loadavg: 1.07 1.09 1.03 4/37 12833
/proc/meminfo: memFree=916932/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.205374 s]
/proc/loadavg: 1.07 1.09 1.03 4/37 12833
/proc/meminfo: memFree=916932/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.305376 s]
/proc/loadavg: 1.07 1.09 1.03 4/37 12833
/proc/meminfo: memFree=916932/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.70553 s]
/proc/loadavg: 1.07 1.09 1.03 4/37 12833
/proc/meminfo: memFree=916932/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.50582 s]
/proc/loadavg: 1.14 1.11 1.04 2/39 12843
/proc/meminfo: memFree=882616/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=1928 CPUtime=0
/proc/12840/stat : 12840 (clasp) S 12831 12831 2160 34817 2160 4202496 273 0 18 0 0 0 0 0 24 0 1 0 56499507 1974272 159 1283457024 134512640 136285277 4291730976 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12840/statm: 482 159 144 433 0 47 0
[pid=12841] ppid=12831 vsize=2584 CPUtime=0
/proc/12841/stat : 12841 (gringo) S 12831 12831 2160 34817 2160 4202496 380 0 24 0 0 0 0 0 23 0 1 0 56499507 2646016 272 1283457024 134512640 136933539 4288268256 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/12841/statm: 646 272 242 592 0 51 0
[pid=12842] ppid=12831 vsize=33364 CPUtime=1.09
/proc/12842/stat : 12842 (cudf2lp) R 12831 12831 2160 34817 2160 4202496 9234 0 15 0 106 3 0 0 25 0 1 0 56499507 34164736 7602 1283457024 134512640 135786343 4294787728 18446744073709551615 135407694 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12842/statm: 8341 7602 135 311 0 8028 0
Current children cumulated CPU time (s) 1.09
Current children cumulated vsize (KiB) 40472

[startup+3.10982 s]
/proc/loadavg: 1.14 1.11 1.04 3/39 12843
/proc/meminfo: memFree=845616/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=0
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 1521 0 0 0 0 0 0 25 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=22100 CPUtime=0.1
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 6241 0 21 0 8 2 0 0 18 0 1 0 56499507 22630400 5066 1283457024 134512640 136285277 4291730976 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 5525 5066 177 433 0 5090 0
[pid=12841] ppid=12831 vsize=31768 CPUtime=1.12
/proc/12841/stat : 12841 (gringo) R 12831 12831 2160 34817 2160 4202496 9619 0 24 0 108 4 0 0 18 0 1 0 56499507 32530432 6314 1283457024 134512640 136933539 4288268256 18446744073709551615 136192636 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12841/statm: 7942 6314 242 592 0 7347 0
[pid=12842] ppid=12831 vsize=32748 CPUtime=1.43
/proc/12842/stat : 12842 (cudf2lp) R 12831 12831 2160 34817 2160 4202496 10526 0 15 0 138 5 0 0 25 0 1 0 56499507 33533952 7989 1283457024 134512640 135786343 4294787728 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/12842/statm: 8187 7989 139 311 0 7874 0
Current children cumulated CPU time (s) 2.65
Current children cumulated vsize (KiB) 89212

[startup+6.31069 s]
/proc/loadavg: 1.13 1.10 1.04 2/38 12843
/proc/meminfo: memFree=739736/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=1.75
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 12050 0 15 0 0 168 7 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=88400 CPUtime=0.52
/proc/12840/stat : 12840 (clasp) S 12831 12831 2160 34817 2160 4202496 25661 0 21 0 42 10 0 0 18 0 1 0 56499507 90521600 21353 1283457024 134512640 136285277 4291730976 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/12840/statm: 22100 21353 177 433 0 21665 0
[pid=12841] ppid=12831 vsize=141808 CPUtime=3.59
/proc/12841/stat : 12841 (gringo) R 12831 12831 2160 34817 2160 4202496 44429 0 24 0 340 19 0 0 21 0 1 0 56499507 145211392 28731 1283457024 134512640 136933539 4288268256 18446744073709551615 136204823 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/12841/statm: 35452 28731 253 592 0 34857 0
Current children cumulated CPU time (s) 5.86
Current children cumulated vsize (KiB) 232804

[startup+12.7026 s]
/proc/loadavg: 1.12 1.10 1.04 2/37 12844
/proc/meminfo: memFree=772744/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=123560 CPUtime=5.29
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 40302 0 21 0 514 15 0 0 25 0 1 0 56499507 126525440 30602 1283457024 134512640 136285277 4291730976 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 30890 30602 234 433 0 30455 0
Current children cumulated CPU time (s) 12.25
Current children cumulated vsize (KiB) 126156

[startup+25.5064 s]
/proc/loadavg: 1.17 1.11 1.04 2/37 12845
/proc/meminfo: memFree=487420/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=412632 CPUtime=18.08
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 112569 0 21 0 1762 46 0 0 25 0 1 0 56499507 422535168 102869 1283457024 134512640 136285277 4291730976 18446744073709551615 134723339 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 103158 102869 234 433 0 102723 0
Current children cumulated CPU time (s) 25.04
Current children cumulated vsize (KiB) 415228

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

[startup+25.6064 s]
/proc/loadavg: 1.17 1.11 1.04 2/37 12845
/proc/meminfo: memFree=487420/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=415292 CPUtime=18.18
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 113209 0 21 0 1772 46 0 0 25 0 1 0 56499507 425259008 103509 1283457024 134512640 136285277 4291730976 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 103823 103509 234 433 0 103388 0
Current children cumulated CPU time (s) 25.14
Current children cumulated vsize (KiB) 417888

[startup+38.4091 s]
/proc/loadavg: 1.15 1.11 1.04 2/37 12846
/proc/meminfo: memFree=227268/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=693908 CPUtime=30.96
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 182853 0 21 0 3028 68 0 0 25 0 1 0 56499507 710561792 173153 1283457024 134512640 136285277 4291730976 18446744073709551615 134669462 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 173477 173153 234 433 0 173042 0
Current children cumulated CPU time (s) 37.92
Current children cumulated vsize (KiB) 696504

[startup+44.8105 s]
/proc/loadavg: 1.13 1.11 1.04 2/37 12847
/proc/meminfo: memFree=53792/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=889172 CPUtime=37.37
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 231702 0 21 0 3646 91 0 0 25 0 1 0 56499507 910512128 222002 1283457024 134512640 136285277 4291730976 18446744073709551615 134639339 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 222293 222002 234 433 0 221858 0
Current children cumulated CPU time (s) 44.33
Current children cumulated vsize (KiB) 891768

[startup+48.0112 s]
/proc/loadavg: 1.20 1.12 1.04 2/37 12847
/proc/meminfo: memFree=4268/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=963928 CPUtime=40.55
/proc/12840/stat : 12840 (clasp) R 12831 12831 2160 34817 2160 4202496 250365 0 21 0 3957 98 0 0 25 0 1 0 56499507 987062272 240665 1283457024 134512640 136285277 4291730976 18446744073709551615 134966737 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/12840/statm: 240982 240665 234 433 0 240547 0
Current children cumulated CPU time (s) 47.51
Current children cumulated vsize (KiB) 966524

[startup+48.8045 s]
/proc/loadavg: 1.20 1.12 1.04 2/37 12847
/proc/meminfo: memFree=4120/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=6.96
/proc/12831/stat : 12831 (aspcud-1.5) S 12830 12831 2160 34817 2160 4202496 580 72235 0 39 0 0 660 36 18 0 1 0 56499506 2658304 298 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/12831/statm: 649 298 251 194 0 36 0
[pid=12840] ppid=12831 vsize=980912 CPUtime=41.33
/proc/12840/stat : 12840 (clasp) D 12831 12831 2160 34817 2160 4202496 254611 0 21 0 4031 102 0 0 25 0 1 0 56499507 1004453888 244911 1283457024 134512640 136285277 4291730976 18446744073709551615 135641886 0 0 6 18944 18446744071564410721 0 0 17 0 0 0 0
/proc/12840/statm: 245228 244911 234 433 0 244793 0
Current children cumulated CPU time (s) 48.29
Current children cumulated vsize (KiB) 983508

[startup+49.4645 s]
/proc/loadavg: 1.20 1.12 1.04 2/37 12847
/proc/meminfo: memFree=4120/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=48.61
/proc/12831/stat : 12831 (aspcud-1.5) D 12830 12831 2160 34817 2160 4202496 641 327745 13 60 0 0 4707 154 18 0 1 0 56499506 2658304 121 1283457024 134512640 135304128 4294678944 18446744073709551615 4158240155 0 65536 4 1132560123 18446744071564332000 0 0 17 0 0 0 0
/proc/12831/statm: 649 121 74 194 0 36 0
Current children cumulated CPU time (s) 48.61
Current children cumulated vsize (KiB) 2596

[startup+49.6045 s]
/proc/loadavg: 1.20 1.12 1.04 2/37 12847
/proc/meminfo: memFree=4120/1048576 swapFree=0/0
[pid=12831] ppid=12830 vsize=2596 CPUtime=48.61
/proc/12831/stat : 12831 (aspcud-1.5) D 12830 12831 2160 34817 2160 4202496 746 327949 22 65 0 0 4707 154 18 0 1 0 56499506 2658304 208 1283457024 134512640 135304128 4294678944 18446744073709551615 4294960130 0 0 16902 1132543225 18446744071564252162 0 0 17 0 0 0 0
/proc/12831/statm: 649 208 161 194 0 36 0
Current children cumulated CPU time (s) 48.61
Current children cumulated vsize (KiB) 2596

Child status: 0
Real time (s): 49.6926
CPU time (s): 48.619
CPU user time (s): 47.0749
CPU system time (s): 1.5441
CPU usage (%): 97.8396
Max. virtual memory (cumulated for all children) (KiB): 987176

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 47.0749
system time used= 1.5441
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 331109
page faults= 93
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 8819
involuntary context switches= 8177

runsolver used 0 second user time and 0.028001 second system time

The end