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/rand455.cudf.dudf-random.log.runsolver ./aspcud-1.5 /home/misc2010/data/2011/dudf-random//rand455.cudf /home/misc2010/tmp/201108311143/aspcud-1.5/rand455.cudf.dudf-random.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.08 1.07 1.01 5/38 24082 /proc/meminfo: memFree=622252/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2588 CPUtime=0 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 374 0 0 0 0 0 0 0 18 0 1 0 62851264 2650112 280 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/24080/statm: 647 280 234 194 0 34 0 [pid=24081] ppid=24080 vsize=2588 CPUtime=0 /proc/24081/stat : 24081 (aspcud-1.5) R 24080 24080 19908 34817 19908 4202560 110 0 0 0 0 0 0 0 25 0 1 0 62851265 2650112 133 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24081/statm: 647 133 86 194 0 34 0 [pid=24082] ppid=24081 vsize=2588 CPUtime=0 /proc/24082/stat : 24082 (aspcud-1.5) R 24081 24080 19908 34817 19908 4202560 0 0 0 0 0 0 0 0 25 0 1 0 62851265 2650112 47 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/24082/statm: 647 47 0 194 0 34 0 [startup+0.15008 s] /proc/loadavg: 1.08 1.07 1.01 5/38 24082 /proc/meminfo: memFree=622252/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=0 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.206513 s] /proc/loadavg: 1.08 1.07 1.01 5/38 24082 /proc/meminfo: memFree=622252/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=0 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.306535 s] /proc/loadavg: 1.08 1.07 1.01 5/38 24082 /proc/meminfo: memFree=622252/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=0 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.706132 s] /proc/loadavg: 1.08 1.07 1.01 5/38 24082 /proc/meminfo: memFree=622252/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=0 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 1520 0 0 0 0 0 0 25 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.507 s] /proc/loadavg: 1.08 1.07 1.01 2/40 24091 /proc/meminfo: memFree=584532/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.24 /proc/24080/stat : 24080 (aspcud-1.5) R 24079 24080 19908 34817 19908 4202496 581 10183 0 0 0 0 120 4 19 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 0 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=3944 CPUtime=0.12 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 877 0 0 0 12 0 0 0 18 0 1 0 62851266 4038656 744 1283457024 134512640 136285277 4288211856 18446744073709551615 134955177 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 986 744 233 433 0 551 0 [pid=24090] ppid=24080 vsize=0 CPUtime=0.04 /proc/24090/stat : 24090 (gringo) Z 24080 24080 19908 34817 19908 4202508 1157 0 0 0 4 0 0 0 18 0 1 0 62851266 0 0 1283457024 0 0 0 0 0 0 0 6 16384 18446744071564254338 0 0 17 0 0 0 0 /proc/24090/statm: 0 0 0 0 0 0 0 Current children cumulated CPU time (s) 1.4 Current children cumulated vsize (KiB) 6540 [startup+3.10729 s] /proc/loadavg: 1.15 1.08 1.02 3/39 24091 /proc/meminfo: memFree=605088/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=3944 CPUtime=1.72 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 884 0 0 0 172 0 0 0 20 0 1 0 62851266 4038656 751 1283457024 134512640 136285277 4288211856 18446744073709551615 134966697 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 986 751 233 433 0 551 0 Current children cumulated CPU time (s) 3 Current children cumulated vsize (KiB) 6540 [startup+6.30787 s] /proc/loadavg: 1.15 1.08 1.02 2/38 24091 /proc/meminfo: memFree=604972/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=3944 CPUtime=4.92 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 884 0 0 0 492 0 0 0 25 0 1 0 62851266 4038656 751 1283457024 134512640 136285277 4288211856 18446744073709551615 134931346 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 986 751 233 433 0 551 0 Current children cumulated CPU time (s) 6.2 Current children cumulated vsize (KiB) 6540 [startup+12.7091 s] /proc/loadavg: 1.13 1.08 1.02 2/38 24091 /proc/meminfo: memFree=604972/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=3944 CPUtime=11.32 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 884 0 0 0 1132 0 0 0 25 0 1 0 62851266 4038656 751 1283457024 134512640 136285277 4288211856 18446744073709551615 134733752 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 986 751 233 433 0 551 0 Current children cumulated CPU time (s) 12.6 Current children cumulated vsize (KiB) 6540 [startup+25.5117 s] /proc/loadavg: 1.11 1.08 1.01 2/38 24091 /proc/meminfo: memFree=604848/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=3944 CPUtime=24.11 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 907 0 0 0 2411 0 0 0 25 0 1 0 62851266 4038656 774 1283457024 134512640 136285277 4288211856 18446744073709551615 134733718 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 986 774 233 433 0 551 0 Current children cumulated CPU time (s) 25.39 Current children cumulated vsize (KiB) 6540 [startup+51.1065 s] /proc/loadavg: 1.07 1.07 1.01 2/38 24091 /proc/meminfo: memFree=604724/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=4028 CPUtime=49.69 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 932 0 0 0 4969 0 0 0 25 0 1 0 62851266 4124672 799 1283457024 134512640 136285277 4288211856 18446744073709551615 134686705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 1007 799 234 433 0 572 0 Current children cumulated CPU time (s) 50.97 Current children cumulated vsize (KiB) 6624 [startup+102.306 s] /proc/loadavg: 1.03 1.06 1.01 2/38 24091 /proc/meminfo: memFree=604476/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=4236 CPUtime=100.88 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 982 0 0 0 10088 0 0 0 25 0 1 0 62851266 4337664 849 1283457024 134512640 136285277 4288211856 18446744073709551615 134955227 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 1059 849 234 433 0 624 0 Current children cumulated CPU time (s) 102.16 Current children cumulated vsize (KiB) 6832 [startup+162.308 s] /proc/loadavg: 1.01 1.04 1.00 2/38 24091 /proc/meminfo: memFree=604476/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=4236 CPUtime=160.85 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 982 0 0 0 16085 0 0 0 25 0 1 0 62851266 4337664 849 1283457024 134512640 136285277 4288211856 18446744073709551615 135668783 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 1059 849 234 433 0 624 0 Current children cumulated CPU time (s) 162.13 Current children cumulated vsize (KiB) 6832 [startup+222.309 s] /proc/loadavg: 1.00 1.03 1.00 2/38 24091 /proc/meminfo: memFree=604476/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=4236 CPUtime=220.82 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 982 0 0 0 22082 0 0 0 25 0 1 0 62851266 4337664 849 1283457024 134512640 136285277 4288211856 18446744073709551615 134959552 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 1059 849 234 433 0 624 0 Current children cumulated CPU time (s) 222.1 Current children cumulated vsize (KiB) 6832 [startup+282.313 s] /proc/loadavg: 1.00 1.03 1.00 2/40 24098 /proc/meminfo: memFree=604204/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=4236 CPUtime=280.79 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 982 0 0 0 28078 1 0 0 25 0 1 0 62851266 4337664 849 1283457024 134512640 136285277 4288211856 18446744073709551615 134930686 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 1059 849 234 433 0 624 0 Current children cumulated CPU time (s) 282.07 Current children cumulated vsize (KiB) 6832 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.305 s] /proc/loadavg: 1.00 1.02 1.00 2/40 24099 /proc/meminfo: memFree=604204/1048576 swapFree=0/0 [pid=24080] ppid=24079 vsize=2596 CPUtime=1.28 /proc/24080/stat : 24080 (aspcud-1.5) S 24079 24080 19908 34817 19908 4202496 581 11340 0 0 0 0 124 4 17 0 1 0 62851264 2658304 299 1283457024 134512640 135304128 4287533840 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/24080/statm: 649 299 251 194 0 36 0 [pid=24089] ppid=24080 vsize=4236 CPUtime=288.78 /proc/24089/stat : 24089 (clasp) R 24080 24080 19908 34817 19908 4202496 982 0 0 0 28877 1 0 0 25 0 1 0 62851266 4337664 849 1283457024 134512640 136285277 4288211856 18446744073709551615 134964942 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/24089/statm: 1059 849 234 433 0 624 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 6832 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.325 CPU time (s): 290.102 CPU user time (s): 290.022 CPU system time (s): 0.080005 CPU usage (%): 99.9232 Max. virtual memory (cumulated for all children) (KiB): 36232 getrusage(RUSAGE_CHILDREN,...) data: user time used= 290.022 system time used= 0.080005 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 16460 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= 141 involuntary context switches= 3654 runsolver used 0 second user time and 0.012 second system time The end