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/rand399.cudf.s-e-l.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l/rand399.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand399.cudf.s-e-l.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.02 1.00 3/36 9937 /proc/meminfo: memFree=686276/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2592 CPUtime=0 /proc/9936/stat : 9936 (aspuncud-trendy) R 9935 9936 1511 34817 1511 4202496 367 0 0 0 0 0 0 0 25 0 1 0 2381407 2654208 280 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/9936/statm: 648 280 234 194 0 35 0 [pid=9937] ppid=9936 vsize=2592 CPUtime=0 /proc/9937/stat : 9937 (aspuncud-trendy) R 9936 9936 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 2381407 2654208 46 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/9937/statm: 648 46 0 194 0 35 0 [startup+0.154495 s] /proc/loadavg: 1.00 1.02 1.00 3/36 9937 /proc/meminfo: memFree=686276/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=0.01 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.206927 s] /proc/loadavg: 1.00 1.02 1.00 3/36 9937 /proc/meminfo: memFree=686276/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=0.01 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.306518 s] /proc/loadavg: 1.00 1.02 1.00 3/36 9937 /proc/meminfo: memFree=686276/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=0.01 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+0.707382 s] /proc/loadavg: 1.00 1.02 1.00 3/36 9937 /proc/meminfo: memFree=686276/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=0.01 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2596 [startup+1.50801 s] /proc/loadavg: 1.00 1.02 1.00 2/39 9950 /proc/meminfo: memFree=644532/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=0.01 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 2227 0 0 0 0 0 1 25 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=7352 CPUtime=0.01 /proc/9948/stat : 9948 (unclasp) S 9936 9936 1511 34817 1511 4202496 1485 0 0 0 1 0 0 0 18 0 1 0 2381408 7528448 1267 1283457024 134512640 135121179 4286745232 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/9948/statm: 1838 1267 275 149 0 1029 0 [pid=9949] ppid=9936 vsize=7644 CPUtime=0.15 /proc/9949/stat : 9949 (gringo) R 9936 9936 1511 34817 1511 4202496 1952 0 0 0 13 2 0 0 18 0 1 0 2381408 7827456 1403 1283457024 134512640 137056543 4294209856 18446744073709551615 136099524 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9949/statm: 1911 1403 253 622 0 1286 0 [pid=9950] ppid=9936 vsize=30572 CPUtime=1.21 /proc/9950/stat : 9950 (cudf2lp) R 9936 9936 1511 34817 1511 4202496 10050 0 0 0 119 2 0 0 25 0 1 0 2381408 31305728 7426 1283457024 134512640 135786343 4291405584 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/9950/statm: 7643 7426 137 311 0 7330 0 Current children cumulated CPU time (s) 1.38 Current children cumulated vsize (KiB) 48164 [startup+3.10858 s] /proc/loadavg: 1.00 1.02 1.00 3/38 9950 /proc/meminfo: memFree=639836/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=30760 CPUtime=0.86 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 12027 0 0 0 85 1 0 0 18 0 1 0 2381408 31498240 6729 1283457024 134512640 135121179 4286745232 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7690 6729 328 149 0 6881 0 Current children cumulated CPU time (s) 2.98 Current children cumulated vsize (KiB) 33356 [startup+6.31002 s] /proc/loadavg: 1.00 1.02 1.00 2/37 9950 /proc/meminfo: memFree=646176/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=30760 CPUtime=4.06 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 38580 0 0 0 392 14 0 0 25 0 1 0 2381408 31498240 6747 1283457024 134512640 135121179 4286745232 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7690 6747 328 149 0 6881 0 Current children cumulated CPU time (s) 6.18 Current children cumulated vsize (KiB) 33356 [startup+12.7126 s] /proc/loadavg: 1.00 1.02 1.00 2/36 9950 /proc/meminfo: memFree=646324/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=31340 CPUtime=10.46 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 91197 0 0 0 1008 38 0 0 25 0 1 0 2381408 32092160 6873 1283457024 134512640 135121179 4286745232 18446744073709551615 134980986 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7835 6873 328 149 0 7026 0 Current children cumulated CPU time (s) 12.58 Current children cumulated vsize (KiB) 33936 Solver just ended. Dumping a history of the last processes samples [startup+12.8127 s] /proc/loadavg: 1.00 1.02 1.00 2/36 9950 /proc/meminfo: memFree=646324/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=30760 CPUtime=10.56 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 91922 0 0 0 1017 39 0 0 25 0 1 0 2381408 31498240 6728 1283457024 134512640 135121179 4286745232 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7690 6728 328 149 0 6881 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 33356 [startup+14.4133 s] /proc/loadavg: 1.00 1.02 1.00 2/36 9950 /proc/meminfo: memFree=646324/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=30760 CPUtime=12.16 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 105227 0 0 0 1168 48 0 0 25 0 1 0 2381408 31498240 6729 1283457024 134512640 135121179 4286745232 18446744073709551615 134734307 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7690 6729 328 149 0 6881 0 Current children cumulated CPU time (s) 14.28 Current children cumulated vsize (KiB) 33356 [startup+16.0039 s] /proc/loadavg: 1.00 1.02 1.00 2/36 9950 /proc/meminfo: memFree=646572/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=30760 CPUtime=13.75 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 118442 0 0 0 1316 59 0 0 25 0 1 0 2381408 31498240 6747 1283457024 134512640 135121179 4286745232 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7690 6747 328 149 0 6881 0 Current children cumulated CPU time (s) 15.87 Current children cumulated vsize (KiB) 33356 [startup+16.4041 s] /proc/loadavg: 1.00 1.02 1.00 2/36 9950 /proc/meminfo: memFree=646572/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=30760 CPUtime=14.15 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 121887 0 0 0 1355 60 0 0 25 0 1 0 2381408 31498240 6729 1283457024 134512640 135121179 4286745232 18446744073709551615 134734450 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7690 6729 328 149 0 6881 0 Current children cumulated CPU time (s) 16.27 Current children cumulated vsize (KiB) 33356 [startup+16.8043 s] /proc/loadavg: 1.00 1.02 1.00 2/36 9950 /proc/meminfo: memFree=646200/1048576 swapFree=0/0 [pid=9936] ppid=9935 vsize=2596 CPUtime=2.12 /proc/9936/stat : 9936 (aspuncud-trendy) S 9935 9936 1511 34817 1511 4202496 623 20332 0 0 0 0 204 8 16 0 1 0 2381407 2658304 298 1283457024 134512640 135304128 4287468288 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/9936/statm: 649 298 251 194 0 36 0 [pid=9948] ppid=9936 vsize=31256 CPUtime=14.55 /proc/9948/stat : 9948 (unclasp) R 9936 9936 1511 34817 1511 4202496 123479 0 0 0 1395 60 0 0 25 0 1 0 2381408 32006144 6871 1283457024 134512640 135121179 4286745232 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/9948/statm: 7814 6871 328 149 0 7005 0 Current children cumulated CPU time (s) 16.67 Current children cumulated vsize (KiB) 33852 Child status: 0 Real time (s): 16.8762 CPU time (s): 16.749 CPU user time (s): 16.041 CPU system time (s): 0.708044 CPU usage (%): 99.2465 Max. virtual memory (cumulated for all children) (KiB): 61296 getrusage(RUSAGE_CHILDREN,...) data: user time used= 16.041 system time used= 0.708044 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 146913 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= 1226 involuntary context switches= 1091 runsolver used 0 second user time and 0.008 second system time The end