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/aspuncud-trendy-1.3/rand946.cudf.s-e-l-s-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand946.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand946.cudf.s-e-l-s-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.27 1.10 1.03 3/34 16899 /proc/meminfo: memFree=466364/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2592 CPUtime=0 /proc/16898/stat : 16898 (aspuncud-trendy) R 16897 16898 1511 34817 1511 4202496 366 0 0 0 0 0 0 0 25 0 1 0 3799985 2654208 280 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/16898/statm: 648 280 234 194 0 35 0 [pid=16899] ppid=16898 vsize=2592 CPUtime=0 /proc/16899/stat : 16899 (aspuncud-trendy) R 16898 16898 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 3799985 2654208 46 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/16899/statm: 648 46 0 194 0 35 0 [startup+0.15657 s] /proc/loadavg: 1.27 1.10 1.03 3/34 16899 /proc/meminfo: memFree=466364/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=0.01 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 2228 0 0 0 0 0 1 25 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.208586 s] /proc/loadavg: 1.27 1.10 1.03 3/34 16899 /proc/meminfo: memFree=466364/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=0.01 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 2228 0 0 0 0 0 1 25 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.304583 s] /proc/loadavg: 1.27 1.10 1.03 3/34 16899 /proc/meminfo: memFree=466364/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=0.01 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 2228 0 0 0 0 0 1 25 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.704596 s] /proc/loadavg: 1.27 1.10 1.03 3/34 16899 /proc/meminfo: memFree=466364/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=0.01 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 2228 0 0 0 0 0 1 25 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50464 s] /proc/loadavg: 1.27 1.10 1.03 2/37 16912 /proc/meminfo: memFree=430648/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=0.01 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 2228 0 0 0 0 0 1 25 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=3444 CPUtime=0 /proc/16910/stat : 16910 (unclasp) S 16898 16898 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 3799986 3526656 271 1283457024 134512640 135121179 4287388464 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16910/statm: 861 271 240 149 0 52 0 [pid=16911] ppid=16898 vsize=2696 CPUtime=0 /proc/16911/stat : 16911 (gringo) S 16898 16898 1511 34817 1511 4202496 408 0 0 0 0 0 0 0 25 0 1 0 3799986 2760704 281 1283457024 134512640 137056543 4289809680 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16911/statm: 674 281 252 622 0 49 0 [pid=16912] ppid=16898 vsize=40664 CPUtime=1.25 /proc/16912/stat : 16912 (cudf2lp) R 16898 16898 1511 34817 1511 4202496 11539 0 0 0 122 3 0 0 25 0 1 0 3799986 41639936 8634 1283457024 134512640 135786343 4291438352 18446744073709551615 134596146 0 0 6 0 0 0 0 17 0 0 0 0 /proc/16912/statm: 10166 8634 126 311 0 9853 0 Current children cumulated CPU time (s) 1.26 Current children cumulated vsize (KiB) 49400 [startup+3.11401 s] /proc/loadavg: 1.27 1.10 1.03 3/37 16912 /proc/meminfo: memFree=393720/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=0.01 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 2228 0 0 0 0 0 1 25 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=18704 CPUtime=0.03 /proc/16910/stat : 16910 (unclasp) S 16898 16898 1511 34817 1511 4202496 4865 0 0 0 3 0 0 0 18 0 1 0 3799986 19152896 4071 1283457024 134512640 135121179 4287388464 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16910/statm: 4676 4071 275 149 0 3867 0 [pid=16911] ppid=16898 vsize=22080 CPUtime=0.85 /proc/16911/stat : 16911 (gringo) R 16898 16898 1511 34817 1511 4202496 6892 0 0 0 83 2 0 0 18 0 1 0 3799986 22609920 4625 1283457024 134512640 137056543 4289809680 18446744073709551615 134710860 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16911/statm: 5520 4625 253 622 0 4895 0 [pid=16912] ppid=16898 vsize=47332 CPUtime=1.97 /proc/16912/stat : 16912 (cudf2lp) R 16898 16898 1511 34817 1511 4202496 16195 0 0 0 192 5 0 0 25 0 1 0 3799986 48467968 11560 1283457024 134512640 135786343 4291438352 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/16912/statm: 11833 11560 137 311 0 11520 0 Current children cumulated CPU time (s) 2.86 Current children cumulated vsize (KiB) 90712 [startup+6.30515 s] /proc/loadavg: 1.33 1.11 1.03 2/35 16912 /proc/meminfo: memFree=403184/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=46980 CPUtime=2.52 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 24186 0 0 0 244 8 0 0 21 0 1 0 3799986 48107520 10577 1283457024 134512640 135121179 4287388464 18446744073709551615 134643517 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11745 10577 328 149 0 10936 0 Current children cumulated CPU time (s) 6.06 Current children cumulated vsize (KiB) 49576 [startup+12.7077 s] /proc/loadavg: 1.30 1.11 1.03 2/35 16912 /proc/meminfo: memFree=403060/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=46088 CPUtime=8.91 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 94316 0 0 0 846 45 0 0 25 0 1 0 3799986 47194112 10349 1283457024 134512640 135121179 4287388464 18446744073709551615 134643448 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11522 10349 333 149 0 10713 0 Current children cumulated CPU time (s) 12.45 Current children cumulated vsize (KiB) 48684 [startup+25.5118 s] /proc/loadavg: 1.23 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402688/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=48008 CPUtime=21.71 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 222352 0 0 0 2066 105 0 0 25 0 1 0 3799986 49160192 10837 1283457024 134512640 135121179 4287388464 18446744073709551615 134959074 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 12002 10837 333 149 0 11193 0 Current children cumulated CPU time (s) 25.25 Current children cumulated vsize (KiB) 50604 Solver just ended. Dumping a history of the last processes samples [startup+25.6119 s] /proc/loadavg: 1.23 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402688/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=48008 CPUtime=21.81 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 223426 0 0 0 2075 106 0 0 25 0 1 0 3799986 49160192 10837 1283457024 134512640 135121179 4287388464 18446744073709551615 134977770 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 12002 10837 333 149 0 11193 0 Current children cumulated CPU time (s) 25.35 Current children cumulated vsize (KiB) 50604 [startup+27.2124 s] /proc/loadavg: 1.23 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402316/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=47240 CPUtime=23.41 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 240976 0 0 0 2222 119 0 0 25 0 1 0 3799986 48373760 10646 1283457024 134512640 135121179 4287388464 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11810 10646 333 149 0 11001 0 Current children cumulated CPU time (s) 26.95 Current children cumulated vsize (KiB) 49836 [startup+28.0126 s] /proc/loadavg: 1.23 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402812/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=47240 CPUtime=24.2 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 250125 0 0 0 2298 122 0 0 25 0 1 0 3799986 48373760 10646 1283457024 134512640 135121179 4287388464 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11810 10646 333 149 0 11001 0 Current children cumulated CPU time (s) 27.74 Current children cumulated vsize (KiB) 49836 [startup+28.4128 s] /proc/loadavg: 1.23 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402812/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=47040 CPUtime=24.61 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 254928 0 0 0 2337 124 0 0 25 0 1 0 3799986 48168960 10596 1283457024 134512640 135121179 4287388464 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11760 10596 333 149 0 10951 0 Current children cumulated CPU time (s) 28.15 Current children cumulated vsize (KiB) 49636 [startup+28.8129 s] /proc/loadavg: 1.21 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402812/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=47040 CPUtime=25.01 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 259423 0 0 0 2376 125 0 0 25 0 1 0 3799986 48168960 10596 1283457024 134512640 135121179 4287388464 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11760 10596 333 149 0 10951 0 Current children cumulated CPU time (s) 28.55 Current children cumulated vsize (KiB) 49636 [startup+28.9031 s] /proc/loadavg: 1.21 1.10 1.03 2/35 16912 /proc/meminfo: memFree=402812/1048576 swapFree=0/0 [pid=16898] ppid=16897 vsize=2596 CPUtime=3.54 /proc/16898/stat : 16898 (aspuncud-trendy) S 16897 16898 1511 34817 1511 4202496 622 32018 0 0 0 0 341 13 15 0 1 0 3799985 2658304 298 1283457024 134512640 135304128 4287447792 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16898/statm: 649 298 251 194 0 36 0 [pid=16910] ppid=16898 vsize=47284 CPUtime=25.1 /proc/16910/stat : 16910 (unclasp) R 16898 16898 1511 34817 1511 4202496 260431 0 0 0 2385 125 0 0 25 0 1 0 3799986 48418816 10689 1283457024 134512640 135121179 4287388464 18446744073709551615 134981270 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16910/statm: 11821 10689 333 149 0 11012 0 Current children cumulated CPU time (s) 28.64 Current children cumulated vsize (KiB) 49880 Child status: 0 Real time (s): 29.0094 CPU time (s): 28.7498 CPU user time (s): 27.3577 CPU system time (s): 1.39209 CPU usage (%): 99.105 Max. virtual memory (cumulated for all children) (KiB): 90760 getrusage(RUSAGE_CHILDREN,...) data: user time used= 27.3577 system time used= 1.39209 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 295884 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= 2165 involuntary context switches= 1905 runsolver used 0 second user time and 0 second system time The end