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/201108311143/aspcud-1.5/80cfe9a6-9b1b-11df-965e-00163e46d37a.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//80cfe9a6-9b1b-11df-965e-00163e46d37a.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/80cfe9a6-9b1b-11df-965e-00163e46d37a.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.10 1.08 1.02 4/36 31089
/proc/meminfo: memFree=677700/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2588 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 373 0 0 0 0 0 0 0 25 0 1 0 66350447 2650112 280 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0
/proc/31086/statm: 647 280 234 194 0 34 0
[pid=31087] ppid=31086 vsize=2588 CPUtime=0
/proc/31087/stat : 31087 (aspcud-1.5) S 31086 31086 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 25 0 1 0 66350447 2650112 134 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0
/proc/31087/statm: 647 134 87 194 0 34 0
[pid=31088] ppid=31087 vsize=2588 CPUtime=0
/proc/31088/stat : 31088 (aspcud-1.5) R 31087 31086 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 66350447 2650112 151 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/31088/statm: 647 151 104 194 0 34 0
[pid=31089] ppid=31088 vsize=2588 CPUtime=0
/proc/31089/stat : 31089 (aspcud-1.5) R 31088 31086 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 66350447 2650112 47 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0
/proc/31089/statm: 647 47 0 194 0 34 0

[startup+0.186484 s]
/proc/loadavg: 1.10 1.08 1.02 4/36 31089
/proc/meminfo: memFree=677700/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 1517 0 0 0 0 0 0 25 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.206424 s]
/proc/loadavg: 1.10 1.08 1.02 4/36 31089
/proc/meminfo: memFree=677700/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 1517 0 0 0 0 0 0 25 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.306438 s]
/proc/loadavg: 1.10 1.08 1.02 4/36 31089
/proc/meminfo: memFree=677700/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 1517 0 0 0 0 0 0 25 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+0.706454 s]
/proc/loadavg: 1.10 1.08 1.02 4/36 31089
/proc/meminfo: memFree=677700/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 1517 0 0 0 0 0 0 25 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2596

[startup+1.5065 s]
/proc/loadavg: 1.10 1.08 1.02 1/37 31097
/proc/meminfo: memFree=666296/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 1517 0 0 0 0 0 0 25 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=1924 CPUtime=0.01
/proc/31095/stat : 31095 (clasp) S 31086 31086 19908 34817 19908 4202496 292 0 0 0 0 1 0 0 25 0 1 0 66350448 1970176 159 1283457024 134512640 136285277 4293783776 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/31095/statm: 481 159 144 433 0 46 0
[pid=31096] ppid=31086 vsize=2584 CPUtime=0
/proc/31096/stat : 31096 (gringo) S 31086 31086 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 66350448 2646016 272 1283457024 134512640 136933539 4286757536 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/31096/statm: 646 272 242 592 0 51 0
[pid=31097] ppid=31086 vsize=8932 CPUtime=0.22
/proc/31097/stat : 31097 (cudf2lp) R 31086 31086 19908 34817 19908 4202496 2401 0 0 0 22 0 0 0 18 0 1 0 66350448 9146368 1908 1283457024 134512640 135786343 4289105136 18446744073709551615 134851472 0 0 6 0 0 0 0 17 0 0 0 0
/proc/31097/statm: 2233 1908 128 311 0 1920 0
Current children cumulated CPU time (s) 0.23
Current children cumulated vsize (KiB) 16036

[startup+3.10665 s]
/proc/loadavg: 1.09 1.08 1.02 1/37 31097
/proc/meminfo: memFree=656864/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=0
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 1517 0 0 0 0 0 0 25 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=1924 CPUtime=0.01
/proc/31095/stat : 31095 (clasp) S 31086 31086 19908 34817 19908 4202496 292 0 0 0 0 1 0 0 25 0 1 0 66350448 1970176 159 1283457024 134512640 136285277 4293783776 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/31095/statm: 481 159 144 433 0 46 0
[pid=31096] ppid=31086 vsize=2584 CPUtime=0
/proc/31096/stat : 31096 (gringo) S 31086 31086 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 66350448 2646016 272 1283457024 134512640 136933539 4286757536 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/31096/statm: 646 272 242 592 0 51 0
[pid=31097] ppid=31086 vsize=16148 CPUtime=0.52
/proc/31097/stat : 31097 (cudf2lp) D 31086 31086 19908 34817 19908 4202496 4575 0 0 0 50 2 0 0 18 0 1 0 66350448 16535552 3729 1283457024 134512640 135786343 4289105136 18446744073709551615 135258478 0 0 6 0 18446744071564332000 0 0 17 0 0 0 0
/proc/31097/statm: 4037 3729 128 311 0 3724 0
Current children cumulated CPU time (s) 0.53
Current children cumulated vsize (KiB) 23252
heavy processes:

[startup+6.30919 s]
/proc/loadavg: 1.09 1.08 1.02 2/35 31097
/proc/meminfo: memFree=647544/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=12984 CPUtime=0.91
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 3648 0 0 0 89 2 0 0 19 0 1 0 66350448 13295616 3008 1283457024 134512640 136285277 4293783776 18446744073709551615 134966782 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 3246 3008 234 433 0 2811 0
Current children cumulated CPU time (s) 2.63
Current children cumulated vsize (KiB) 15580
heavy processes:

[startup+12.7105 s]
/proc/loadavg: 1.08 1.07 1.02 2/35 31097
/proc/meminfo: memFree=633168/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=30036 CPUtime=7.29
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 7920 0 0 0 724 5 0 0 25 0 1 0 66350448 30756864 7280 1283457024 134512640 136285277 4293783776 18446744073709551615 134959560 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 7509 7280 234 433 0 7074 0
Current children cumulated CPU time (s) 9.01
Current children cumulated vsize (KiB) 32632
heavy processes:

[startup+25.5134 s]
/proc/loadavg: 1.07 1.07 1.02 2/35 31097
/proc/meminfo: memFree=624364/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=36368 CPUtime=20.08
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 9482 0 0 0 2003 5 0 0 25 0 1 0 66350448 37240832 8842 1283457024 134512640 136285277 4293783776 18446744073709551615 134966710 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 9092 8842 234 433 0 8657 0
Current children cumulated CPU time (s) 21.8
Current children cumulated vsize (KiB) 38964

[startup+51.1121 s]
/proc/loadavg: 1.04 1.06 1.01 2/35 31097
/proc/meminfo: memFree=621388/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=39808 CPUtime=45.64
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 10214 0 0 0 4559 5 0 0 25 0 1 0 66350448 40763392 9574 1283457024 134512640 136285277 4293783776 18446744073709551615 134963355 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 9952 9574 234 433 0 9517 0
Current children cumulated CPU time (s) 47.36
Current children cumulated vsize (KiB) 42404

[startup+102.307 s]
/proc/loadavg: 1.02 1.05 1.01 2/35 31097
/proc/meminfo: memFree=612336/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=48864 CPUtime=96.74
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 12668 0 0 0 9667 7 0 0 25 0 1 0 66350448 50036736 11819 1283457024 134512640 136285277 4293783776 18446744073709551615 134959497 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 12216 11819 234 433 0 11781 0
Current children cumulated CPU time (s) 98.46
Current children cumulated vsize (KiB) 51460

[startup+162.312 s]
/proc/loadavg: 1.00 1.04 1.00 2/37 31101
/proc/meminfo: memFree=599912/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=60944 CPUtime=156.62
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 15695 0 0 0 15654 8 0 0 25 0 1 0 66350448 62406656 14846 1283457024 134512640 136285277 4293783776 18446744073709551615 134955218 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 15236 14846 234 433 0 14801 0
Current children cumulated CPU time (s) 158.34
Current children cumulated vsize (KiB) 63540

[startup+222.308 s]
/proc/loadavg: 1.00 1.03 1.00 2/37 31107
/proc/meminfo: memFree=599912/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=60944 CPUtime=216.5
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 15695 0 0 0 21640 10 0 0 25 0 1 0 66350448 62406656 14846 1283457024 134512640 136285277 4293783776 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 15236 14846 234 433 0 14801 0
Current children cumulated CPU time (s) 218.22
Current children cumulated vsize (KiB) 63540

[startup+282.311 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 31108
/proc/meminfo: memFree=599928/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=60944 CPUtime=276.47
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 15695 0 0 0 27637 10 0 0 25 0 1 0 66350448 62406656 14846 1283457024 134512640 136285277 4293783776 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 15236 14846 234 433 0 14801 0
Current children cumulated CPU time (s) 278.19
Current children cumulated vsize (KiB) 63540



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+294.213 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 31108
/proc/meminfo: memFree=599928/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=60944 CPUtime=288.37
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 15695 0 0 0 28827 10 0 0 25 0 1 0 66350448 62406656 14846 1283457024 134512640 136285277 4293783776 18446744073709551615 134669902 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 15236 14846 234 433 0 14801 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 63540

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+294.213 s]
/proc/loadavg: 1.00 1.02 1.00 2/36 31108
/proc/meminfo: memFree=599928/1048576 swapFree=0/0
[pid=31086] ppid=31085 vsize=2596 CPUtime=1.72
/proc/31086/stat : 31086 (aspcud-1.5) S 31085 31086 19908 34817 19908 4202496 581 17197 0 0 0 0 166 6 15 0 1 0 66350447 2658304 299 1283457024 134512640 135304128 4290643408 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31086/statm: 649 299 251 194 0 36 0
[pid=31095] ppid=31086 vsize=60944 CPUtime=288.37
/proc/31095/stat : 31095 (clasp) R 31086 31086 19908 34817 19908 4202496 15695 0 0 0 28827 10 0 0 25 0 1 0 66350448 62406656 14846 1283457024 134512640 136285277 4293783776 18446744073709551615 134669902 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31095/statm: 15236 14846 234 433 0 14801 0
Current children cumulated CPU time (s) 290.09
Current children cumulated vsize (KiB) 63540

Child status: 0
Real time (s): 294.24
CPU time (s): 290.118
CPU user time (s): 289.942
CPU system time (s): 0.176011
CPU usage (%): 98.599
Max. virtual memory (cumulated for all children) (KiB): 63540

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.942
system time used= 0.176011
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 37148
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= 224
involuntary context switches= 3646

runsolver used 0 second user time and 0 second system time

The end