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/rand438.cudf.user-upgrades.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/user-upgrades/rand438.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand438.cudf.user-upgrades.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.13 1.09 1.03 5/38 24966 /proc/meminfo: memFree=834308/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2588 CPUtime=0 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 18 0 1 0 63232560 2650112 280 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/24964/statm: 647 280 234 194 0 34 0 [pid=24965] ppid=24964 vsize=2588 CPUtime=0 /proc/24965/stat : 24965 (aspcud-1.5) S 24964 24964 19908 34817 19908 4202560 118 0 0 0 0 0 0 0 25 0 1 0 63232561 2650112 134 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/24965/statm: 647 134 87 194 0 34 0 [pid=24966] ppid=24965 vsize=2588 CPUtime=0 /proc/24966/stat : 24966 (aspcud-1.5) R 24965 24964 19908 34817 19908 4202560 127 0 0 0 0 0 0 0 25 0 1 0 63232561 2650112 151 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24966/statm: 647 151 104 194 0 34 0 [pid=24967] ppid=24966 vsize=2588 CPUtime=0 /proc/24967/stat : 24967 (aspcud-1.5) R 24966 24964 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 63232561 2650112 47 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24967/statm: 647 47 0 194 0 34 0 [startup+0.165996 s] /proc/loadavg: 1.13 1.09 1.03 5/38 24966 /proc/meminfo: memFree=834308/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=0 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.204582 s] /proc/loadavg: 1.13 1.09 1.03 5/38 24966 /proc/meminfo: memFree=834308/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=0 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306076 s] /proc/loadavg: 1.13 1.09 1.03 5/38 24966 /proc/meminfo: memFree=834308/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=0 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.704615 s] /proc/loadavg: 1.13 1.09 1.03 5/38 24966 /proc/meminfo: memFree=834308/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=0 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50465 s] /proc/loadavg: 1.13 1.09 1.03 2/40 24975 /proc/meminfo: memFree=801704/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=0 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 1521 0 0 0 0 0 0 25 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=1932 CPUtime=0 /proc/24973/stat : 24973 (clasp) S 24964 24964 19908 34817 19908 4202496 293 0 0 0 0 0 0 0 25 0 1 0 63232562 1978368 160 1283457024 134512640 136285277 4290545088 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/24973/statm: 483 160 144 433 0 48 0 [pid=24974] ppid=24964 vsize=2580 CPUtime=0 /proc/24974/stat : 24974 (gringo) S 24964 24964 19908 34817 19908 4202496 404 0 0 0 0 0 0 0 25 0 1 0 63232562 2641920 271 1283457024 134512640 136933539 4290547264 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/24974/statm: 645 271 242 592 0 50 0 [pid=24975] ppid=24964 vsize=28108 CPUtime=1.3 /proc/24975/stat : 24975 (cudf2lp) R 24964 24964 19908 34817 19908 4202496 8032 0 0 0 125 5 0 0 25 0 1 0 63232562 28782592 6287 1283457024 134512640 135786343 4294423040 18446744073709551615 134625464 0 0 6 0 0 0 0 17 0 0 0 0 /proc/24975/statm: 7027 6287 128 311 0 6714 0 Current children cumulated CPU time (s) 1.3 Current children cumulated vsize (KiB) 35216 [startup+3.11111 s] /proc/loadavg: 1.13 1.09 1.03 2/40 24975 /proc/meminfo: memFree=762760/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.26 /proc/24964/stat : 24964 (aspcud-1.5) R 24963 24964 19908 34817 19908 4202496 581 15495 0 0 0 0 218 8 19 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=3752 CPUtime=0.5 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 848 0 0 0 50 0 0 0 18 0 1 0 63232562 3842048 712 1283457024 134512640 136285277 4290545088 18446744073709551615 134955202 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 938 712 233 433 0 503 0 [pid=24974] ppid=24964 vsize=0 CPUtime=0.05 /proc/24974/stat : 24974 (gringo) Z 24964 24964 19908 34817 19908 4202508 883 0 0 0 5 0 0 0 18 0 1 0 63232562 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/24974/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 2.81 Current children cumulated vsize (KiB) 6348 [startup+6.31173 s] /proc/loadavg: 1.20 1.11 1.03 2/38 24975 /proc/meminfo: memFree=801604/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=4160 CPUtime=3.7 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 967 0 0 0 370 0 0 0 25 0 1 0 63232562 4259840 831 1283457024 134512640 136285277 4290545088 18446744073709551615 134649414 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1040 831 234 433 0 605 0 Current children cumulated CPU time (s) 6.02 Current children cumulated vsize (KiB) 6756 [startup+12.7031 s] /proc/loadavg: 1.19 1.11 1.03 2/38 24975 /proc/meminfo: memFree=801108/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=4640 CPUtime=10.09 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1079 0 0 0 1009 0 0 0 25 0 1 0 63232562 4751360 942 1283457024 134512640 136285277 4290545088 18446744073709551615 134931380 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1160 942 234 433 0 725 0 Current children cumulated CPU time (s) 12.41 Current children cumulated vsize (KiB) 7236 [startup+25.5061 s] /proc/loadavg: 1.14 1.10 1.03 2/38 24975 /proc/meminfo: memFree=800736/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=4972 CPUtime=22.89 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1173 0 0 0 2289 0 0 0 25 0 1 0 63232562 5091328 1014 1283457024 134512640 136285277 4290545088 18446744073709551615 134723304 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1243 1014 234 433 0 808 0 Current children cumulated CPU time (s) 25.21 Current children cumulated vsize (KiB) 7568 [startup+51.1127 s] /proc/loadavg: 1.09 1.09 1.03 2/40 24979 /proc/meminfo: memFree=800092/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=5396 CPUtime=48.47 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1298 0 0 0 4847 0 0 0 25 0 1 0 63232562 5525504 1133 1283457024 134512640 136285277 4290545088 18446744073709551615 134733725 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1349 1133 234 433 0 914 0 Current children cumulated CPU time (s) 50.79 Current children cumulated vsize (KiB) 7992 [startup+102.314 s] /proc/loadavg: 1.04 1.08 1.02 2/40 24984 /proc/meminfo: memFree=799472/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=5812 CPUtime=99.65 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1406 0 0 0 9965 0 0 0 25 0 1 0 63232562 5951488 1236 1283457024 134512640 136285277 4290545088 18446744073709551615 134966831 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1453 1236 234 433 0 1018 0 Current children cumulated CPU time (s) 101.97 Current children cumulated vsize (KiB) 8408 [startup+162.306 s] /proc/loadavg: 1.01 1.06 1.02 2/39 24986 /proc/meminfo: memFree=799364/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=5976 CPUtime=159.6 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1475 0 0 0 15959 1 0 0 25 0 1 0 63232562 6119424 1276 1283457024 134512640 136285277 4290545088 18446744073709551615 134960029 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1494 1276 234 433 0 1059 0 Current children cumulated CPU time (s) 161.92 Current children cumulated vsize (KiB) 8572 [startup+222.307 s] /proc/loadavg: 1.00 1.05 1.01 2/38 24986 /proc/meminfo: memFree=799372/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=6104 CPUtime=219.58 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1514 0 0 0 21956 2 0 0 25 0 1 0 63232562 6250496 1315 1283457024 134512640 136285277 4290545088 18446744073709551615 134669477 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1526 1315 234 433 0 1091 0 Current children cumulated CPU time (s) 221.9 Current children cumulated vsize (KiB) 8700 [startup+282.31 s] /proc/loadavg: 1.00 1.04 1.01 2/38 24986 /proc/meminfo: memFree=799248/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=6236 CPUtime=279.56 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1535 0 0 0 27954 2 0 0 25 0 1 0 63232562 6385664 1336 1283457024 134512640 136285277 4290545088 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1559 1336 234 433 0 1124 0 Current children cumulated CPU time (s) 281.88 Current children cumulated vsize (KiB) 8832 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.512 s] /proc/loadavg: 1.00 1.03 1.01 2/38 24986 /proc/meminfo: memFree=799248/1048576 swapFree=0/0 [pid=24964] ppid=24963 vsize=2596 CPUtime=2.32 /proc/24964/stat : 24964 (aspcud-1.5) S 24963 24964 19908 34817 19908 4202496 581 16378 0 0 0 0 224 8 17 0 1 0 63232560 2658304 299 1283457024 134512640 135304128 4287177392 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24964/statm: 649 299 251 194 0 36 0 [pid=24973] ppid=24964 vsize=6236 CPUtime=287.76 /proc/24973/stat : 24973 (clasp) R 24964 24964 19908 34817 19908 4202496 1535 0 0 0 28774 2 0 0 25 0 1 0 63232562 6385664 1336 1283457024 134512640 136285277 4290545088 18446744073709551615 135658630 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24973/statm: 1559 1336 234 433 0 1124 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 8832 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples Child status: 0 Real time (s): 290.532 CPU time (s): 290.106 CPU user time (s): 289.982 CPU system time (s): 0.124007 CPU usage (%): 99.8534 Max. virtual memory (cumulated for all children) (KiB): 55320 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.982 system time used= 0.124007 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22039 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= 188 involuntary context switches= 3720 runsolver used 0.008 second user time and 0 second system time The end