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/8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf.dudf-real.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-real//8b0e7c16-bab4-11e0-a883-00163e1e087d.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/8b0e7c16-bab4-11e0-a883-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.00 1.03 1.00 5/34 31937
/proc/meminfo: memFree=579956/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2588 CPUtime=0
/proc/31936/stat : 31936 (aspcud-1.5) R 31935 31936 19908 34817 19908 4202496 366 0 0 0 0 0 0 0 25 0 1 0 66788230 2650112 279 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/31936/statm: 647 279 234 194 0 34 0
[pid=31937] ppid=31936 vsize=2588 CPUtime=0
/proc/31937/stat : 31937 (aspcud-1.5) R 31936 31936 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 66788230 2650112 45 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/31937/statm: 647 45 0 194 0 34 0

[startup+0.156863 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 31937
/proc/meminfo: memFree=579956/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=0.01
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 1520 0 0 0 0 1 0 25 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.204817 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 31937
/proc/meminfo: memFree=579956/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=0.01
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 1520 0 0 0 0 1 0 25 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.304849 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 31937
/proc/meminfo: memFree=579956/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=0.01
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 1520 0 0 0 0 1 0 25 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+0.704916 s]
/proc/loadavg: 1.00 1.03 1.00 5/34 31937
/proc/meminfo: memFree=579956/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=0.01
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 1520 0 0 0 0 1 0 25 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
Current children cumulated CPU time (s) 0.01
Current children cumulated vsize (KiB) 2596

[startup+1.5049 s]
/proc/loadavg: 1.00 1.03 1.00 2/37 31947
/proc/meminfo: memFree=558724/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=0.01
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 1520 0 0 0 0 1 0 25 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=1928 CPUtime=0
/proc/31945/stat : 31945 (clasp) S 31936 31936 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 66788231 1974272 159 1283457024 134512640 136285277 4293519520 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/31945/statm: 482 159 144 433 0 47 0
[pid=31946] ppid=31936 vsize=2584 CPUtime=0
/proc/31946/stat : 31946 (gringo) S 31936 31936 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 66788231 2646016 272 1283457024 134512640 136933539 4293097648 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/31946/statm: 646 272 242 592 0 51 0
[pid=31947] ppid=31936 vsize=16832 CPUtime=0.53
/proc/31947/stat : 31947 (cudf2lp) R 31936 31936 19908 34817 19908 4202496 4763 0 0 0 52 1 0 0 25 0 1 0 66788231 17235968 3966 1283457024 134512640 135786343 4289662320 18446744073709551615 134566259 0 0 6 0 0 0 0 17 0 0 0 0
/proc/31947/statm: 4208 3966 128 311 0 3895 0
Current children cumulated CPU time (s) 0.54
Current children cumulated vsize (KiB) 23940

[startup+3.10907 s]
/proc/loadavg: 1.00 1.03 1.00 2/37 31947
/proc/meminfo: memFree=539472/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=0.01
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 1520 0 0 0 0 1 0 25 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=1928 CPUtime=0
/proc/31945/stat : 31945 (clasp) S 31936 31936 19908 34817 19908 4202496 292 0 0 0 0 0 0 0 25 0 1 0 66788231 1974272 159 1283457024 134512640 136285277 4293519520 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0
/proc/31945/statm: 482 159 144 433 0 47 0
[pid=31946] ppid=31936 vsize=2584 CPUtime=0
/proc/31946/stat : 31946 (gringo) S 31936 31936 19908 34817 19908 4202496 405 0 0 0 0 0 0 0 25 0 1 0 66788231 2646016 272 1283457024 134512640 136933539 4293097648 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0
/proc/31946/statm: 646 272 242 592 0 51 0
[pid=31947] ppid=31936 vsize=45488 CPUtime=1.3
/proc/31947/stat : 31947 (cudf2lp) R 31936 31936 19908 34817 19908 4202496 12521 0 0 0 125 5 0 0 25 0 1 0 66788231 46579712 11019 1283457024 134512640 135786343 4289662320 18446744073709551615 134582072 0 0 6 0 0 0 0 17 0 0 0 0
/proc/31947/statm: 11372 11019 135 311 0 11059 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 52596
heavy processes:

[startup+6.3098 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 31947
/proc/meminfo: memFree=557052/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2748 CPUtime=2.88
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 597 0 0 0 288 0 0 0 24 0 1 0 66788231 2813952 460 1283457024 134512640 136285277 4293519520 18446744073709551615 134718496 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 687 460 233 433 0 252 0
Current children cumulated CPU time (s) 4.5
Current children cumulated vsize (KiB) 5344
heavy processes:

[startup+12.7112 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 31947
/proc/meminfo: memFree=557060/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2748 CPUtime=9.28
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 597 0 0 0 928 0 0 0 25 0 1 0 66788231 2813952 460 1283457024 134512640 136285277 4293519520 18446744073709551615 134948853 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 687 460 233 433 0 252 0
Current children cumulated CPU time (s) 10.9
Current children cumulated vsize (KiB) 5344

[startup+25.5044 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 31947
/proc/meminfo: memFree=557060/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2748 CPUtime=22.06
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 597 0 0 0 2206 0 0 0 25 0 1 0 66788231 2813952 460 1283457024 134512640 136285277 4293519520 18446744073709551615 134975752 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 687 460 233 433 0 252 0
Current children cumulated CPU time (s) 23.68
Current children cumulated vsize (KiB) 5344

[startup+51.1094 s]
/proc/loadavg: 1.00 1.03 1.00 2/35 31947
/proc/meminfo: memFree=557060/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2748 CPUtime=47.65
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 607 0 0 0 4765 0 0 0 25 0 1 0 66788231 2813952 470 1283457024 134512640 136285277 4293519520 18446744073709551615 134955207 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 687 470 233 433 0 252 0
Current children cumulated CPU time (s) 49.27
Current children cumulated vsize (KiB) 5344

[startup+102.31 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 31947
/proc/meminfo: memFree=557060/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2748 CPUtime=98.81
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 617 0 0 0 9880 1 0 0 25 0 1 0 66788231 2813952 480 1283457024 134512640 136285277 4293519520 18446744073709551615 134948639 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 687 480 233 433 0 252 0
Current children cumulated CPU time (s) 100.43
Current children cumulated vsize (KiB) 5344

[startup+162.312 s]
/proc/loadavg: 1.00 1.02 1.00 2/35 31947
/proc/meminfo: memFree=557060/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2872 CPUtime=158.77
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 623 0 0 0 15875 2 0 0 25 0 1 0 66788231 2940928 486 1283457024 134512640 136285277 4293519520 18446744073709551615 134615185 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 718 486 234 433 0 283 0
Current children cumulated CPU time (s) 160.39
Current children cumulated vsize (KiB) 5468

[startup+222.305 s]
/proc/loadavg: 1.00 1.01 1.00 2/37 31954
/proc/meminfo: memFree=556788/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2872 CPUtime=218.71
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 623 0 0 0 21869 2 0 0 25 0 1 0 66788231 2940928 486 1283457024 134512640 136285277 4293519520 18446744073709551615 134735672 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 718 486 234 433 0 283 0
Current children cumulated CPU time (s) 220.33
Current children cumulated vsize (KiB) 5468

[startup+282.316 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 31958
/proc/meminfo: memFree=556680/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2872 CPUtime=278.7
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 623 0 0 0 27865 5 0 0 25 0 1 0 66788231 2940928 486 1283457024 134512640 136285277 4293519520 18446744073709551615 134959535 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 718 486 234 433 0 283 0
Current children cumulated CPU time (s) 280.32
Current children cumulated vsize (KiB) 5468



Maximum CPU time exceeded: sending signal-name then SIGKILL

[startup+292.008 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 31958
/proc/meminfo: memFree=556680/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2872 CPUtime=288.38
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 623 0 0 0 28833 5 0 0 25 0 1 0 66788231 2940928 486 1283457024 134512640 136285277 4293519520 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 718 486 234 433 0 283 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 5468

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+292.008 s]
/proc/loadavg: 1.00 1.00 1.00 2/36 31958
/proc/meminfo: memFree=556680/1048576 swapFree=0/0
[pid=31936] ppid=31935 vsize=2596 CPUtime=1.62
/proc/31936/stat : 31936 (aspcud-1.5) S 31935 31936 19908 34817 19908 4202496 581 15733 0 0 0 0 155 7 18 0 1 0 66788230 2658304 298 1283457024 134512640 135304128 4293613728 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0
/proc/31936/statm: 649 298 251 194 0 36 0
[pid=31945] ppid=31936 vsize=2872 CPUtime=288.38
/proc/31945/stat : 31945 (clasp) R 31936 31936 19908 34817 19908 4202496 623 0 0 0 28833 5 0 0 25 0 1 0 66788231 2940928 486 1283457024 134512640 136285277 4293519520 18446744073709551615 134959488 0 0 6 18944 0 0 0 17 0 0 0 0
/proc/31945/statm: 718 486 234 433 0 283 0
Current children cumulated CPU time (s) 290
Current children cumulated vsize (KiB) 5468

Child status: 0
Real time (s): 292.027
CPU time (s): 290.038
CPU user time (s): 289.894
CPU system time (s): 0.144009
CPU usage (%): 99.3189
Max. virtual memory (cumulated for all children) (KiB): 52596

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 289.894
system time used= 0.144009
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 20496
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= 183
involuntary context switches= 3664

runsolver used 0 second user time and 0 second system time

The end