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/201108241238/aspcud-trendy-1.5/rand208.cudf.s-e-l-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s/rand208.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand208.cudf.s-e-l-s.result 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.03 1.01 1.00 5/37 4186 /proc/meminfo: memFree=598580/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2588 CPUtime=0 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 372 0 0 0 0 0 0 0 18 0 1 0 1092608 2650112 279 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/4184/statm: 647 279 234 194 0 34 0 [pid=4185] ppid=4184 vsize=2588 CPUtime=0 /proc/4185/stat : 4185 (aspcud-trendy-1) R 4184 4184 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 1092609 2650112 132 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/4185/statm: 647 132 86 194 0 34 0 [pid=4186] ppid=4185 vsize=2588 CPUtime=0 /proc/4186/stat : 4186 (aspcud-trendy-1) R 4185 4184 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 1092609 2650112 46 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/4186/statm: 647 46 0 194 0 34 0 [startup+0.185516 s] /proc/loadavg: 1.03 1.01 1.00 5/37 4186 /proc/meminfo: memFree=598580/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=0.01 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 617 2234 0 0 0 0 0 1 25 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.20551 s] /proc/loadavg: 1.03 1.01 1.00 5/37 4186 /proc/meminfo: memFree=598580/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=0.01 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 617 2234 0 0 0 0 0 1 25 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.305527 s] /proc/loadavg: 1.03 1.01 1.00 5/37 4186 /proc/meminfo: memFree=598580/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=0.01 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 617 2234 0 0 0 0 0 1 25 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.705582 s] /proc/loadavg: 1.03 1.01 1.00 5/37 4186 /proc/meminfo: memFree=598580/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=0.01 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 617 2234 0 0 0 0 0 1 25 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50569 s] /proc/loadavg: 1.03 1.01 1.00 2/39 4199 /proc/meminfo: memFree=577712/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=0.01 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 617 2234 0 0 0 0 0 1 25 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=1932 CPUtime=0 /proc/4196/stat : 4196 (clasp) S 4184 4184 1511 34817 1511 4202496 292 0 0 0 0 0 0 0 25 0 1 0 1092610 1978368 160 1283457024 134512640 136285277 4289156192 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/4196/statm: 483 160 144 433 0 48 0 [pid=4197] ppid=4184 vsize=2588 CPUtime=0 /proc/4197/stat : 4197 (gringo) S 4184 4184 1511 34817 1511 4202496 404 0 0 0 0 0 0 0 25 0 1 0 1092610 2650112 272 1283457024 134512640 136933539 4290905728 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/4197/statm: 647 272 242 592 0 52 0 [pid=4198] ppid=4184 vsize=40444 CPUtime=1.49 /proc/4198/stat : 4198 (cudf2lp) R 4184 4184 1511 34817 1511 4202496 11648 0 0 0 147 2 0 0 25 0 1 0 1092610 41414656 8738 1283457024 134512640 135786343 4288015328 18446744073709551615 134580686 0 0 6 0 0 0 0 17 0 0 0 0 /proc/4198/statm: 10111 8738 131 311 0 9798 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 47560 [startup+3.10588 s] /proc/loadavg: 1.03 1.01 1.00 3/39 4199 /proc/meminfo: memFree=542992/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=2.12 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 17930 0 0 0 0 208 4 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=20784 CPUtime=0.06 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 5902 0 0 0 4 2 0 0 18 0 1 0 1092610 21282816 4706 1283457024 134512640 136285277 4289156192 18446744073709551615 4294960130 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 5196 4706 177 433 0 4761 0 [pid=4197] ppid=4184 vsize=33304 CPUtime=0.91 /proc/4197/stat : 4197 (gringo) R 4184 4184 1511 34817 1511 4202496 9892 0 0 0 90 1 0 0 18 0 1 0 1092610 34103296 6209 1283457024 134512640 136933539 4290905728 18446744073709551615 134885030 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/4197/statm: 8326 6209 253 592 0 7731 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 56684 [startup+6.30679 s] /proc/loadavg: 1.03 1.01 1.00 2/37 4199 /proc/meminfo: memFree=546124/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=53824 CPUtime=2.32 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 16403 0 0 0 224 8 0 0 21 0 1 0 1092610 55115776 13191 1283457024 134512640 136285277 4289156192 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 13456 13191 234 433 0 13021 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 56420 [startup+12.7085 s] /proc/loadavg: 1.02 1.01 1.00 2/37 4200 /proc/meminfo: memFree=546140/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=53824 CPUtime=8.72 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 16417 0 0 0 864 8 0 0 25 0 1 0 1092610 55115776 13205 1283457024 134512640 136285277 4289156192 18446744073709551615 134733705 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 13456 13205 234 433 0 13021 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 56420 [startup+25.5035 s] /proc/loadavg: 1.02 1.01 1.00 2/37 4201 /proc/meminfo: memFree=508444/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=91976 CPUtime=21.5 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 25955 0 0 0 2138 12 0 0 25 0 1 0 1092610 94183424 22743 1283457024 134512640 136285277 4289156192 18446744073709551615 134930783 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 22994 22743 234 433 0 22559 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 94572 [startup+51.1096 s] /proc/loadavg: 1.01 1.01 1.00 2/37 4204 /proc/meminfo: memFree=470252/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=131056 CPUtime=47.1 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 35718 0 0 0 4691 19 0 0 25 0 1 0 1092610 134201344 32506 1283457024 134512640 136285277 4289156192 18446744073709551615 134723291 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 32764 32506 234 433 0 32329 0 Current children cumulated CPU time (s) 51.07 Current children cumulated vsize (KiB) 133652 [startup+102.314 s] /proc/loadavg: 1.00 1.00 1.00 2/36 4204 /proc/meminfo: memFree=376772/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=223572 CPUtime=98.25 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 58811 0 0 0 9793 32 0 0 25 0 1 0 1092610 228937728 55599 1283457024 134512640 136285277 4289156192 18446744073709551615 134623648 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 55893 55599 234 433 0 55458 0 Current children cumulated CPU time (s) 102.22 Current children cumulated vsize (KiB) 226168 [startup+162.309 s] /proc/loadavg: 1.00 1.00 1.00 2/35 4204 /proc/meminfo: memFree=321476/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=282928 CPUtime=158.19 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 73645 0 0 0 15780 39 0 0 25 0 1 0 1092610 289718272 70433 1283457024 134512640 136285277 4289156192 18446744073709551615 134930675 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 70732 70433 234 433 0 70297 0 Current children cumulated CPU time (s) 162.16 Current children cumulated vsize (KiB) 285524 [startup+222.307 s] /proc/loadavg: 1.00 1.00 1.00 2/35 4204 /proc/meminfo: memFree=298412/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=301752 CPUtime=218.15 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 78363 0 0 0 21773 42 0 0 25 0 1 0 1092610 308994048 75151 1283457024 134512640 136285277 4289156192 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 75438 75151 234 433 0 75003 0 Current children cumulated CPU time (s) 222.12 Current children cumulated vsize (KiB) 304348 [startup+282.313 s] /proc/loadavg: 1.00 1.00 1.00 2/35 4204 /proc/meminfo: memFree=209628/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=390776 CPUtime=278.11 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 100686 0 0 0 27747 64 0 0 25 0 1 0 1092610 400154624 97338 1283457024 134512640 136285277 4289156192 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 97694 97338 234 433 0 97259 0 Current children cumulated CPU time (s) 282.08 Current children cumulated vsize (KiB) 393372 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.305 s] /proc/loadavg: 1.00 1.00 1.00 2/35 4204 /proc/meminfo: memFree=208636/1048576 swapFree=0/0 [pid=4184] ppid=4183 vsize=2596 CPUtime=3.97 /proc/4184/stat : 4184 (aspcud-trendy-1) S 4183 4184 1511 34817 1511 4202496 618 37194 0 0 0 0 390 7 18 0 1 0 1092608 2658304 298 1283457024 134512640 135304128 4290952784 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/4184/statm: 649 298 251 194 0 36 0 [pid=4196] ppid=4184 vsize=391832 CPUtime=286.09 /proc/4196/stat : 4196 (clasp) R 4184 4184 1511 34817 1511 4202496 100925 0 0 0 28545 64 0 0 25 0 1 0 1092610 401235968 97577 1283457024 134512640 136285277 4289156192 18446744073709551615 134945922 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/4196/statm: 97958 97577 234 433 0 97523 0 Current children cumulated CPU time (s) 290.06 Current children cumulated vsize (KiB) 394428 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.351 CPU time (s): 290.118 CPU user time (s): 289.374 CPU system time (s): 0.744046 CPU usage (%): 99.9199 Max. virtual memory (cumulated for all children) (KiB): 394428 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.374 system time used= 0.744046 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 142461 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= 2746 involuntary context switches= 5617 runsolver used 0 second user time and 0 second system time The end