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/rand953.cudf.s-e-l-s-s.log.runsolver ./aspcud-trendy-1.5 /home/misc2010/data/2011/incremental/s-e-l-s-s//rand953.cudf /home/misc2010/tmp/201108241238/aspcud-trendy-1.5/rand953.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.00 1.06 1.04 5/35 18829 /proc/meminfo: memFree=567360/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2584 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 4166697 2646016 279 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/18827/statm: 646 279 234 194 0 33 0 [pid=18828] ppid=18827 vsize=2584 CPUtime=0 /proc/18828/stat : 18828 (aspcud-trendy-1) R 18827 18827 1511 34817 1511 4202560 110 0 0 0 0 0 0 0 25 0 1 0 4166697 2646016 132 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/18828/statm: 646 132 86 194 0 33 0 [pid=18829] ppid=18828 vsize=2584 CPUtime=0 /proc/18829/stat : 18829 (aspcud-trendy-1) R 18828 18827 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4166697 2646016 46 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/18829/statm: 646 46 0 194 0 33 0 [startup+0.163758 s] /proc/loadavg: 1.00 1.06 1.04 5/35 18829 /proc/meminfo: memFree=567360/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 622 2231 0 0 0 0 0 0 25 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.213759 s] /proc/loadavg: 1.00 1.06 1.04 5/35 18829 /proc/meminfo: memFree=567360/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 622 2231 0 0 0 0 0 0 25 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.303774 s] /proc/loadavg: 1.00 1.06 1.04 5/35 18829 /proc/meminfo: memFree=567360/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 622 2231 0 0 0 0 0 0 25 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+0.703889 s] /proc/loadavg: 1.00 1.06 1.04 5/35 18829 /proc/meminfo: memFree=567360/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 622 2231 0 0 0 0 0 0 25 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2592 [startup+1.50405 s] /proc/loadavg: 1.00 1.06 1.04 2/37 18841 /proc/meminfo: memFree=546616/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 622 2231 0 0 0 0 0 0 25 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=1928 CPUtime=0.01 /proc/18839/stat : 18839 (clasp) S 18827 18827 1511 34817 1511 4202496 292 0 0 0 0 1 0 0 25 0 1 0 4166698 1974272 159 1283457024 134512640 136285277 4293703856 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/18839/statm: 482 159 144 433 0 47 0 [pid=18840] ppid=18827 vsize=2588 CPUtime=0 /proc/18840/stat : 18840 (gringo) S 18827 18827 1511 34817 1511 4202496 405 0 0 0 0 0 0 0 25 0 1 0 4166699 2650112 272 1283457024 134512640 136933539 4293581072 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18840/statm: 647 272 242 592 0 52 0 [pid=18841] ppid=18827 vsize=40668 CPUtime=1.48 /proc/18841/stat : 18841 (cudf2lp) R 18827 18827 1511 34817 1511 4202496 11687 0 0 0 145 3 0 0 25 0 1 0 4166699 41644032 8776 1283457024 134512640 135786343 4292847728 18446744073709551615 135199389 0 0 6 0 0 0 0 17 0 0 0 0 /proc/18841/statm: 10167 8776 126 311 0 9854 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 47776 [startup+3.10447 s] /proc/loadavg: 1.00 1.06 1.04 3/37 18841 /proc/meminfo: memFree=512392/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=0 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 622 2231 0 0 0 0 0 0 25 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=17320 CPUtime=0.09 /proc/18839/stat : 18839 (clasp) S 18827 18827 1511 34817 1511 4202496 4796 0 0 0 7 2 0 0 18 0 1 0 4166698 17735680 4005 1283457024 134512640 136285277 4293703856 18446744073709551615 4294960130 0 0 6 18944 18446744071564457842 0 0 17 0 0 0 0 /proc/18839/statm: 4330 4005 177 433 0 3895 0 [pid=18840] ppid=18827 vsize=22096 CPUtime=0.76 /proc/18840/stat : 18840 (gringo) S 18827 18827 1511 34817 1511 4202496 6892 0 0 0 72 4 0 0 18 0 1 0 4166699 22626304 4619 1283457024 134512640 136933539 4293581072 18446744073709551615 135633806 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/18840/statm: 5524 4619 242 592 0 4929 0 [pid=18841] ppid=18827 vsize=18104 CPUtime=2.23 /proc/18841/stat : 18841 (cudf2lp) R 18827 18827 1511 34817 1511 4202496 16202 0 0 0 217 6 0 0 25 0 1 0 4166699 18538496 4319 1283457024 134512640 135786343 4292847728 18446744073709551615 135196004 0 0 6 0 0 0 0 17 0 0 0 0 /proc/18841/statm: 4526 4319 138 311 0 4213 0 Current children cumulated CPU time (s) 3.08 Current children cumulated vsize (KiB) 60112 [startup+6.3054 s] /proc/loadavg: 1.00 1.06 1.04 2/35 18841 /proc/meminfo: memFree=512184/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=55612 CPUtime=2.16 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 17267 0 0 0 206 10 0 0 20 0 1 0 4166698 56946688 13657 1283457024 134512640 136285277 4293703856 18446744073709551615 134893169 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 13903 13657 234 433 0 13468 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 58204 [startup+12.7073 s] /proc/loadavg: 1.00 1.06 1.04 2/35 18841 /proc/meminfo: memFree=512936/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=55612 CPUtime=8.55 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 17285 0 0 0 845 10 0 0 25 0 1 0 4166698 56946688 13675 1283457024 134512640 136285277 4293703856 18446744073709551615 134734690 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 13903 13675 234 433 0 13468 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 58204 [startup+25.5113 s] /proc/loadavg: 1.00 1.05 1.04 2/35 18841 /proc/meminfo: memFree=456888/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=112152 CPUtime=21.34 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 31415 0 0 0 2118 16 0 0 25 0 1 0 4166698 114843648 27805 1283457024 134512640 136285277 4293703856 18446744073709551615 134650868 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 28038 27805 234 433 0 27603 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 114744 [startup+51.1079 s] /proc/loadavg: 1.00 1.05 1.04 2/35 18841 /proc/meminfo: memFree=443744/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=125432 CPUtime=46.91 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 34705 0 0 0 4675 16 0 0 25 0 1 0 4166698 128442368 31095 1283457024 134512640 136285277 4293703856 18446744073709551615 134669408 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 31358 31095 234 433 0 30923 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 128024 [startup+102.311 s] /proc/loadavg: 1.00 1.04 1.03 2/35 18841 /proc/meminfo: memFree=353472/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=215600 CPUtime=98.06 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 57218 0 0 0 9779 27 0 0 25 0 1 0 4166698 220774400 53608 1283457024 134512640 136285277 4293703856 18446744073709551615 134669900 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 53900 53608 234 433 0 53465 0 Current children cumulated CPU time (s) 102.19 Current children cumulated vsize (KiB) 218192 [startup+162.309 s] /proc/loadavg: 1.00 1.03 1.03 2/37 18848 /proc/meminfo: memFree=232796/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=335836 CPUtime=158.02 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 87261 0 0 0 15768 34 0 0 25 0 1 0 4166698 343896064 83651 1283457024 134512640 136285277 4293703856 18446744073709551615 134723310 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 83959 83651 234 433 0 83524 0 Current children cumulated CPU time (s) 162.15 Current children cumulated vsize (KiB) 338428 [startup+222.315 s] /proc/loadavg: 1.00 1.02 1.02 2/36 18852 /proc/meminfo: memFree=126296/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=442536 CPUtime=217.98 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 114085 0 0 0 21744 54 0 0 25 0 1 0 4166698 453156864 110234 1283457024 134512640 136285277 4293703856 18446744073709551615 134985131 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 110634 110234 234 433 0 110199 0 Current children cumulated CPU time (s) 222.11 Current children cumulated vsize (KiB) 445128 [startup+282.306 s] /proc/loadavg: 1.00 1.02 1.01 2/35 18852 /proc/meminfo: memFree=50168/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=520316 CPUtime=277.95 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 133650 0 0 0 27732 63 0 0 25 0 1 0 4166698 532803584 129642 1283457024 134512640 136285277 4293703856 18446744073709551615 134959509 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 130079 129642 234 433 0 129644 0 Current children cumulated CPU time (s) 282.08 Current children cumulated vsize (KiB) 522908 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.31 s] /proc/loadavg: 1.00 1.02 1.01 2/35 18852 /proc/meminfo: memFree=31692/1048576 swapFree=0/0 [pid=18827] ppid=18826 vsize=2592 CPUtime=4.13 /proc/18827/stat : 18827 (aspcud-trendy-1) S 18826 18827 1511 34817 1511 4202496 623 38049 0 0 0 0 396 17 18 0 1 0 4166697 2654208 298 1283457024 134512640 135304128 4293482672 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/18827/statm: 648 298 251 194 0 35 0 [pid=18839] ppid=18827 vsize=537212 CPUtime=285.94 /proc/18839/stat : 18839 (clasp) R 18827 18827 1511 34817 1511 4202496 137878 0 0 0 28526 68 0 0 25 0 1 0 4166698 550105088 133870 1283457024 134512640 136285277 4293703856 18446744073709551615 134967003 0 0 6 18944 0 0 0 17 0 0 0 0 /proc/18839/statm: 134303 133870 234 433 0 133868 0 Current children cumulated CPU time (s) 290.07 Current children cumulated vsize (KiB) 539804 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.369 CPU time (s): 290.138 CPU user time (s): 289.242 CPU system time (s): 0.896056 CPU usage (%): 99.9206 Max. virtual memory (cumulated for all children) (KiB): 539804 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.242 system time used= 0.896056 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 180255 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= 2902 involuntary context switches= 5776 runsolver used 0 second user time and 0.008 second system time The end