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/cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//cb0e73b0-0ffd-11df-9e59-00163e2c8d72.cudf /home/misc2010/tmp/201108300820/aspcud-1.5/cb0e73b0-0ffd-11df-9e59-00163e2c8d72.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.00 1.00 1.00 3/33 15687
/proc/meminfo: memFree=932596/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=944 CPUtime=0
/proc/15687/stat : 15687 (aspcud-1.5) R 15686 15687 2160 34817 2160 4194304 82 0 0 0 0 0 0 0 25 0 1 0 58098470 966656 9 1283457024 134512640 135304128 4289729776 18446744073709551615 4160433792 0 0 0 0 0 0 0 17 0 0 0 0
/proc/15687/statm: 236 9 4 194 0 8 0

[startup+0.180488 s]
/proc/loadavg: 1.00 1.00 1.00 3/33 15687
/proc/meminfo: memFree=932596/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=0
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 1519 0 0 0 0 0 0 25 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.204486 s]
/proc/loadavg: 1.00 1.00 1.00 3/33 15687
/proc/meminfo: memFree=932596/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=0
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 1519 0 0 0 0 0 0 25 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.304454 s]
/proc/loadavg: 1.00 1.00 1.00 3/33 15687
/proc/meminfo: memFree=932596/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=0
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 1519 0 0 0 0 0 0 25 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.704487 s]
/proc/loadavg: 1.00 1.00 1.00 3/33 15687
/proc/meminfo: memFree=932596/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=0
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 1519 0 0 0 0 0 0 25 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.51147 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 15698
/proc/meminfo: memFree=894596/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=0
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 1519 0 0 0 0 0 0 25 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=6796 CPUtime=0.03
/proc/15696/stat : 15696 (clasp) S 15687 15687 2160 34817 2160 4202496 1615 0 22 0 3 0 0 0 18 0 1 0 58098471 6959104 1422 1283457024 134512640 136285277 4287793312 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/15696/statm: 1699 1422 177 433 0 1264 0
[pid=15697] ppid=15687 vsize=9856 CPUtime=0.27
/proc/15697/stat : 15697 (gringo) R 15687 15687 2160 34817 2160 4202496 2557 0 23 0 27 0 0 0 18 0 1 0 58098471 10092544 1850 1283457024 134512640 136933539 4291989968 18446744073709551615 134741956 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15697/statm: 2464 1850 242 592 0 1869 0
[pid=15698] ppid=15687 vsize=22724 CPUtime=0.8
/proc/15698/stat : 15698 (cudf2lp) R 15687 15687 2160 34817 2160 4202496 6916 0 15 0 76 4 0 0 25 0 1 0 58098471 23269376 5502 1283457024 134512640 135786343 4292920704 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0
/proc/15698/statm: 5681 5502 139 311 0 5368 0
Current children cumulated CPU time (s) 1.1
Current children cumulated vsize (KiB) 41972

[startup+3.1119 s]
/proc/loadavg: 1.00 1.00 1.00 4/37 15698
/proc/meminfo: memFree=863476/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=1.11
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 8438 0 15 0 0 104 7 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=34272 CPUtime=0.11
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 9865 0 22 0 11 0 0 0 18 0 1 0 58098471 35094528 8082 1283457024 134512640 136285277 4287793312 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 8568 8082 177 433 0 8133 0
[pid=15697] ppid=15687 vsize=49760 CPUtime=1.48
/proc/15697/stat : 15697 (gringo) R 15687 15687 2160 34817 2160 4202496 15600 0 23 0 142 6 0 0 18 0 1 0 58098471 50954240 10976 1283457024 134512640 136933539 4291989968 18446744073709551615 134909636 0 0 6 16384 0 0 0 17 0 0 0 0
/proc/15697/statm: 12440 10976 253 592 0 11845 0
Current children cumulated CPU time (s) 2.7
Current children cumulated vsize (KiB) 86628

[startup+6.30265 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 15698
/proc/meminfo: memFree=761812/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=85288 CPUtime=1.21
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 26559 0 22 0 112 9 0 0 18 0 1 0 58098471 87334912 20989 1283457024 134512640 136285277 4287793312 18446744073709551615 135639472 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 21322 20989 216 433 0 20887 0
Current children cumulated CPU time (s) 5.9
Current children cumulated vsize (KiB) 87884

[startup+12.7141 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15698
/proc/meminfo: memFree=834128/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=85288 CPUtime=7.62
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 26590 0 22 0 753 9 0 0 25 0 1 0 58098471 87334912 21020 1283457024 134512640 136285277 4287793312 18446744073709551615 134911280 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 21322 21020 220 433 0 20887 0
Current children cumulated CPU time (s) 12.31
Current children cumulated vsize (KiB) 87884

[startup+25.5075 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 15700
/proc/meminfo: memFree=699440/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=219288 CPUtime=20.39
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 60326 0 22 0 2022 17 0 0 25 0 1 0 58098471 224550912 54575 1283457024 134512640 136285277 4287793312 18446744073709551615 134649003 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 54822 54575 235 433 0 54387 0
Current children cumulated CPU time (s) 25.08
Current children cumulated vsize (KiB) 221884

[startup+51.1074 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 15703
/proc/meminfo: memFree=695844/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=231556 CPUtime=45.93
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 64895 0 22 0 4575 18 0 0 25 0 1 0 58098471 237113344 57618 1283457024 134512640 136285277 4287793312 18446744073709551615 134963461 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 57889 57618 235 433 0 57454 0
Current children cumulated CPU time (s) 50.62
Current children cumulated vsize (KiB) 234152

[startup+102.313 s]
/proc/loadavg: 1.00 1.00 1.00 2/37 15708
/proc/meminfo: memFree=460120/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=458820 CPUtime=96.98
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 124741 0 22 0 9655 43 0 0 25 0 1 0 58098471 469831680 114400 1283457024 134512640 136285277 4287793312 18446744073709551615 134963461 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 114705 114400 235 433 0 114270 0
Current children cumulated CPU time (s) 101.67
Current children cumulated vsize (KiB) 461416

[startup+162.307 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 15709
/proc/meminfo: memFree=217964/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=704540 CPUtime=156.84
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 186289 0 22 0 15611 73 0 0 25 0 1 0 58098471 721448960 175812 1283457024 134512640 136285277 4287793312 18446744073709551615 134651231 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 176135 175812 235 433 0 175700 0
Current children cumulated CPU time (s) 161.53
Current children cumulated vsize (KiB) 707136

[startup+222.304 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15709
/proc/meminfo: memFree=214004/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=704540 CPUtime=216.72
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 186294 0 22 0 21598 74 0 0 25 0 1 0 58098471 721448960 175817 1283457024 134512640 136285277 4287793312 18446744073709551615 134955200 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 176135 175817 235 433 0 175700 0
Current children cumulated CPU time (s) 221.41
Current children cumulated vsize (KiB) 707136

[startup+282.314 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15709
/proc/meminfo: memFree=214004/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=704540 CPUtime=276.61
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 186294 0 22 0 27586 75 0 0 25 0 1 0 58098471 721448960 175817 1283457024 134512640 136285277 4287793312 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 176135 175817 235 433 0 175700 0
Current children cumulated CPU time (s) 281.3
Current children cumulated vsize (KiB) 707136



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+291.107 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15709
/proc/meminfo: memFree=214004/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=2596 CPUtime=4.69
/proc/15687/stat : 15687 (aspcud-1.5) S 15686 15687 2160 34817 2160 4202496 582 45905 0 38 0 0 441 28 18 0 1 0 58098470 2658304 299 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/15687/statm: 649 299 251 194 0 36 0
[pid=15696] ppid=15687 vsize=704540 CPUtime=285.38
/proc/15696/stat : 15696 (clasp) R 15687 15687 2160 34817 2160 4202496 186294 0 22 0 28463 75 0 0 25 0 1 0 58098471 721448960 175817 1283457024 134512640 136285277 4287793312 18446744073709551615 134639147 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/15696/statm: 176135 175817 235 433 0 175700 0
Current children cumulated CPU time (s) 290.07
Current children cumulated vsize (KiB) 707136

Sending User defined signal 1 to process tree (bottom up)
Sleeping 10 seconds

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

[startup+291.234 s]
/proc/loadavg: 1.00 1.00 1.00 2/35 15709
/proc/meminfo: memFree=214004/1048576 swapFree=0/0
[pid=15687] ppid=15686 vsize=5672 CPUtime=290.16
/proc/15687/stat : 15687 (aspcud-1.5) R 15686 15687 2160 34817 2160 4202496 1416 234024 0 60 2 0 28906 108 25 0 1 0 58098470 5808128 902 1283457024 134512640 135304128 4289729776 18446744073709551615 4294960130 0 65536 16902 1132543225 0 0 0 17 0 0 0 0
/proc/15687/statm: 1418 902 261 194 0 805 0
Current children cumulated CPU time (s) 290.16
Current children cumulated vsize (KiB) 5672

Child status: 0
Real time (s): 291.272
CPU time (s): 290.254
CPU user time (s): 289.154
CPU system time (s): 1.10007
CPU usage (%): 99.6506
Max. virtual memory (cumulated for all children) (KiB): 707136

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.154
system time used= 1.10007
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 239567
page faults= 60
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 5859
involuntary context switches= 8523

runsolver used 0 second user time and 0 second system time

The end