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/rand230.cudf.s-e-l-s-s.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand230.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand230.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.19 1.10 1.00 5/38 3851 /proc/meminfo: memFree=642728/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2592 CPUtime=0 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 375 0 0 0 0 0 0 0 18 0 1 0 972227 2654208 280 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/3848/statm: 648 280 234 194 0 35 0 [pid=3849] ppid=3848 vsize=2592 CPUtime=0 /proc/3849/stat : 3849 (aspuncud-trendy) S 3848 3848 1511 34817 1511 4202560 118 0 0 0 0 0 0 0 18 0 1 0 972227 2654208 134 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/3849/statm: 648 134 87 194 0 35 0 [pid=3850] ppid=3849 vsize=2592 CPUtime=0 /proc/3850/stat : 3850 (aspuncud-trendy) R 3849 3848 1511 34817 1511 4202560 126 0 0 0 0 0 0 0 25 0 1 0 972227 2654208 151 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/3850/statm: 648 151 104 194 0 35 0 [pid=3851] ppid=3850 vsize=2592 CPUtime=0 /proc/3851/stat : 3851 (aspuncud-trendy) R 3850 3848 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 972227 2654208 47 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/3851/statm: 648 47 0 194 0 35 0 [startup+0.16703 s] /proc/loadavg: 1.19 1.10 1.00 5/38 3851 /proc/meminfo: memFree=642728/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=0.01 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.214889 s] /proc/loadavg: 1.19 1.10 1.00 5/38 3851 /proc/meminfo: memFree=642728/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=0.01 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.303041 s] /proc/loadavg: 1.19 1.10 1.00 5/38 3851 /proc/meminfo: memFree=642728/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=0.01 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.707365 s] /proc/loadavg: 1.19 1.10 1.00 5/38 3851 /proc/meminfo: memFree=642728/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=0.01 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50711 s] /proc/loadavg: 1.19 1.10 1.00 2/39 3863 /proc/meminfo: memFree=609200/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=0.01 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=3440 CPUtime=0 /proc/3860/stat : 3860 (unclasp) S 3848 3848 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 972228 3522560 271 1283457024 134512640 135121179 4293275856 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3860/statm: 860 271 240 149 0 51 0 [pid=3861] ppid=3848 vsize=2688 CPUtime=0 /proc/3861/stat : 3861 (gringo) S 3848 3848 1511 34817 1511 4202496 407 0 0 0 0 0 0 0 25 0 1 0 972228 2752512 280 1283457024 134512640 137056543 4293353584 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3861/statm: 672 280 252 622 0 47 0 [pid=3862] ppid=3848 vsize=22336 CPUtime=0.95 /proc/3862/stat : 3862 (cudf2lp) R 3848 3848 1511 34817 1511 4202496 6738 0 0 0 91 4 0 0 23 0 1 0 972228 22872064 5242 1283457024 134512640 135786343 4289561936 18446744073709551615 134852471 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3862/statm: 5584 5242 126 311 0 5271 0 Current children cumulated CPU time (s) 0.96 Current children cumulated vsize (KiB) 31060 [startup+3.1048 s] /proc/loadavg: 1.19 1.10 1.00 2/39 3863 /proc/meminfo: memFree=574120/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=0.01 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 2226 0 0 0 0 0 1 25 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=14200 CPUtime=0.06 /proc/3860/stat : 3860 (unclasp) S 3848 3848 1511 34817 1511 4202496 3489 0 0 0 6 0 0 0 18 0 1 0 972228 14540800 2967 1283457024 134512640 135121179 4293275856 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/3860/statm: 3550 2967 275 149 0 2741 0 [pid=3861] ppid=3848 vsize=17788 CPUtime=0.57 /proc/3861/stat : 3861 (gringo) R 3848 3848 1511 34817 1511 4202496 5174 0 0 0 55 2 0 0 18 0 1 0 972228 18214912 3421 1283457024 134512640 137056543 4293353584 18446744073709551615 134699078 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3861/statm: 4447 3421 253 622 0 3822 0 [pid=3862] ppid=3848 vsize=47332 CPUtime=1.88 /proc/3862/stat : 3862 (cudf2lp) R 3848 3848 1511 34817 1511 4202496 16195 0 0 0 180 8 0 0 25 0 1 0 972228 48467968 11560 1283457024 134512640 135786343 4289561936 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/3862/statm: 11833 11560 137 311 0 11520 0 Current children cumulated CPU time (s) 2.52 Current children cumulated vsize (KiB) 81916 [startup+6.30591 s] /proc/loadavg: 1.26 1.11 1.01 2/37 3863 /proc/meminfo: memFree=579988/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=46740 CPUtime=2.28 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 24246 0 0 0 220 8 0 0 21 0 1 0 972228 47861760 10517 1283457024 134512640 135121179 4293275856 18446744073709551615 134874165 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 11685 10517 328 149 0 10876 0 Current children cumulated CPU time (s) 5.72 Current children cumulated vsize (KiB) 49336 [startup+12.7085 s] /proc/loadavg: 1.24 1.11 1.00 2/37 3864 /proc/meminfo: memFree=579368/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=47224 CPUtime=8.69 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 100658 0 0 0 842 27 0 0 25 0 1 0 972228 48357376 10637 1283457024 134512640 135121179 4293275856 18446744073709551615 134734459 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 11806 10637 333 149 0 10997 0 Current children cumulated CPU time (s) 12.13 Current children cumulated vsize (KiB) 49820 [startup+25.5128 s] /proc/loadavg: 1.18 1.10 1.00 2/37 3865 /proc/meminfo: memFree=578500/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=48228 CPUtime=21.48 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 211869 0 0 0 2072 76 0 0 25 0 1 0 972228 49385472 10885 1283457024 134512640 135121179 4293275856 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 12057 10885 333 149 0 11248 0 Current children cumulated CPU time (s) 24.92 Current children cumulated vsize (KiB) 50824 Solver just ended. Dumping a history of the last processes samples [startup+25.6128 s] /proc/loadavg: 1.18 1.10 1.00 2/37 3865 /proc/meminfo: memFree=578500/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=48228 CPUtime=21.58 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 212217 0 0 0 2082 76 0 0 25 0 1 0 972228 49385472 10885 1283457024 134512640 135121179 4293275856 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 12057 10885 333 149 0 11248 0 Current children cumulated CPU time (s) 25.02 Current children cumulated vsize (KiB) 50824 [startup+27.2134 s] /proc/loadavg: 1.18 1.10 1.00 2/37 3865 /proc/meminfo: memFree=579120/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=47272 CPUtime=23.18 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 229498 0 0 0 2230 88 0 0 25 0 1 0 972228 48406528 10684 1283457024 134512640 135121179 4293275856 18446744073709551615 134734361 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 11818 10684 333 149 0 11009 0 Current children cumulated CPU time (s) 26.62 Current children cumulated vsize (KiB) 49868 [startup+28.0137 s] /proc/loadavg: 1.18 1.10 1.00 2/37 3865 /proc/meminfo: memFree=579120/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=47688 CPUtime=23.97 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 237146 0 0 0 2306 91 0 0 25 0 1 0 972228 48832512 10754 1283457024 134512640 135121179 4293275856 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 11922 10754 333 149 0 11113 0 Current children cumulated CPU time (s) 27.41 Current children cumulated vsize (KiB) 50284 [startup+28.8139 s] /proc/loadavg: 1.17 1.10 1.00 2/37 3865 /proc/meminfo: memFree=578376/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=47272 CPUtime=24.77 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 241611 0 0 0 2382 95 0 0 25 0 1 0 972228 48406528 10684 1283457024 134512640 135121179 4293275856 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 11818 10684 333 149 0 11009 0 Current children cumulated CPU time (s) 28.21 Current children cumulated vsize (KiB) 49868 [startup+29.014 s] /proc/loadavg: 1.17 1.10 1.00 2/37 3865 /proc/meminfo: memFree=578376/1048576 swapFree=0/0 [pid=3848] ppid=3847 vsize=2596 CPUtime=3.44 /proc/3848/stat : 3848 (aspuncud-trendy) S 3847 3848 1511 34817 1511 4202496 625 32052 0 0 0 0 325 19 15 0 1 0 972227 2658304 298 1283457024 134512640 135304128 4292646880 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/3848/statm: 649 298 251 194 0 36 0 [pid=3860] ppid=3848 vsize=47504 CPUtime=24.97 /proc/3860/stat : 3860 (unclasp) R 3848 3848 1511 34817 1511 4202496 244026 0 0 0 2398 99 0 0 25 0 1 0 972228 48644096 10709 1283457024 134512640 135121179 4293275856 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/3860/statm: 11876 10709 333 149 0 11067 0 Current children cumulated CPU time (s) 28.41 Current children cumulated vsize (KiB) 50100 Child status: 0 Real time (s): 29.1041 CPU time (s): 28.5218 CPU user time (s): 27.3137 CPU system time (s): 1.20807 CPU usage (%): 97.999 Max. virtual memory (cumulated for all children) (KiB): 90896 getrusage(RUSAGE_CHILDREN,...) data: user time used= 27.3137 system time used= 1.20808 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 279540 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= 2157 involuntary context switches= 1900 runsolver used 0 second user time and 0.008 second system time The end