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/rand797.cudf.s-e-l.log.runsolver ./aspuncud-trendy-1.3 /home/misc2010/data/2011/incremental/s-e-l/rand797.cudf /home/misc2010/tmp/201108241238/aspuncud-trendy-1.3/rand797.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 5/36 19242 /proc/meminfo: memFree=543784/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2584 CPUtime=0 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 373 0 0 0 0 0 0 0 18 0 1 0 4366087 2646016 279 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/19239/statm: 646 279 234 194 0 33 0 [pid=19240] ppid=19239 vsize=2584 CPUtime=0 /proc/19240/stat : 19240 (aspuncud-trendy) S 19239 19239 1511 34817 1511 4202560 119 0 0 0 0 0 0 0 18 0 1 0 4366087 2646016 133 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 0 0 65538 18446744071564457842 0 0 17 0 0 0 0 /proc/19240/statm: 646 133 87 194 0 33 0 [pid=19241] ppid=19240 vsize=2584 CPUtime=0 /proc/19241/stat : 19241 (aspuncud-trendy) R 19240 19239 1511 34817 1511 4202560 127 0 0 0 0 0 0 0 25 0 1 0 4366087 2646016 150 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/19241/statm: 646 150 104 194 0 33 0 [pid=19242] ppid=19241 vsize=2584 CPUtime=0 /proc/19242/stat : 19242 (aspuncud-trendy) R 19241 19239 1511 34817 1511 4202560 0 0 0 0 0 0 0 0 25 0 1 0 4366087 2646016 46 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/19242/statm: 646 46 0 194 0 33 0 [startup+0.145615 s] /proc/loadavg: 1.00 1.02 1.00 5/36 19242 /proc/meminfo: memFree=543784/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=0 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 622 2229 0 0 0 0 0 0 25 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.209171 s] /proc/loadavg: 1.00 1.02 1.00 5/36 19242 /proc/meminfo: memFree=543784/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=0 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 622 2229 0 0 0 0 0 0 25 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.301704 s] /proc/loadavg: 1.00 1.02 1.00 5/36 19242 /proc/meminfo: memFree=543784/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=0 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 622 2229 0 0 0 0 0 0 25 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+0.705644 s] /proc/loadavg: 1.00 1.02 1.00 5/36 19242 /proc/meminfo: memFree=543784/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=0 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 622 2229 0 0 0 0 0 0 25 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2588 [startup+1.51102 s] /proc/loadavg: 1.00 1.02 1.00 2/37 19253 /proc/meminfo: memFree=501144/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=0 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 622 2229 0 0 0 0 0 0 25 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=7488 CPUtime=0 /proc/19251/stat : 19251 (unclasp) S 19239 19239 1511 34817 1511 4202496 1521 0 0 0 0 0 0 0 18 0 1 0 4366088 7667712 1304 1283457024 134512640 135121179 4287304480 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/19251/statm: 1872 1304 275 149 0 1063 0 [pid=19252] ppid=19239 vsize=8676 CPUtime=0.23 /proc/19252/stat : 19252 (gringo) R 19239 19239 1511 34817 1511 4202496 2253 0 0 0 23 0 0 0 18 0 1 0 4366088 8884224 1448 1283457024 134512640 137056543 4292138816 18446744073709551615 136301899 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19252/statm: 2169 1448 253 622 0 1544 0 [pid=19253] ppid=19239 vsize=30576 CPUtime=1.14 /proc/19253/stat : 19253 (cudf2lp) R 19239 19239 1511 34817 1511 4202496 10049 0 0 0 109 5 0 0 25 0 1 0 4366089 31309824 7426 1283457024 134512640 135786343 4290668128 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/19253/statm: 7644 7426 137 311 0 7331 0 Current children cumulated CPU time (s) 1.37 Current children cumulated vsize (KiB) 49328 [startup+3.11153 s] /proc/loadavg: 1.08 1.04 1.01 3/36 19253 /proc/meminfo: memFree=497068/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=2.15 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 623 20390 0 0 0 0 202 13 15 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=30780 CPUtime=0.84 /proc/19251/stat : 19251 (unclasp) R 19239 19239 1511 34817 1511 4202496 12320 0 0 0 79 5 0 0 18 0 1 0 4366088 31518720 6767 1283457024 134512640 135121179 4287304480 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19251/statm: 7695 6767 328 149 0 6886 0 Current children cumulated CPU time (s) 2.99 Current children cumulated vsize (KiB) 33368 [startup+6.31288 s] /proc/loadavg: 1.08 1.04 1.01 2/35 19253 /proc/meminfo: memFree=503408/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=2.15 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 623 20390 0 0 0 0 202 13 15 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=30780 CPUtime=4.03 /proc/19251/stat : 19251 (unclasp) R 19239 19239 1511 34817 1511 4202496 36075 0 0 0 387 16 0 0 25 0 1 0 4366088 31518720 6772 1283457024 134512640 135121179 4287304480 18446744073709551615 134643485 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19251/statm: 7695 6772 333 149 0 6886 0 Current children cumulated CPU time (s) 6.18 Current children cumulated vsize (KiB) 33368 Solver just ended. Dumping a history of the last processes samples [startup+6.40291 s] /proc/loadavg: 1.08 1.04 1.01 2/35 19253 /proc/meminfo: memFree=503408/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=2.15 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 623 20390 0 0 0 0 202 13 15 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=31064 CPUtime=4.12 /proc/19251/stat : 19251 (unclasp) R 19239 19239 1511 34817 1511 4202496 36292 0 0 0 396 16 0 0 25 0 1 0 4366088 31809536 6843 1283457024 134512640 135121179 4287304480 18446744073709551615 134891225 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19251/statm: 7766 6843 333 149 0 6957 0 Current children cumulated CPU time (s) 6.27 Current children cumulated vsize (KiB) 33652 [startup+8.00364 s] /proc/loadavg: 1.07 1.04 1.00 2/35 19253 /proc/meminfo: memFree=503044/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=2.15 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 623 20390 0 0 0 0 202 13 15 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=30944 CPUtime=5.72 /proc/19251/stat : 19251 (unclasp) R 19239 19239 1511 34817 1511 4202496 49457 0 0 0 542 30 0 0 25 0 1 0 4366088 31686656 6832 1283457024 134512640 135121179 4287304480 18446744073709551615 134734256 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19251/statm: 7736 6832 333 149 0 6927 0 Current children cumulated CPU time (s) 7.87 Current children cumulated vsize (KiB) 33532 [startup+8.40381 s] /proc/loadavg: 1.07 1.04 1.00 2/35 19253 /proc/meminfo: memFree=503044/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=2.15 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 623 20390 0 0 0 0 202 13 15 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=31784 CPUtime=6.12 /proc/19251/stat : 19251 (unclasp) R 19239 19239 1511 34817 1511 4202496 51584 0 0 0 579 33 0 0 25 0 1 0 4366088 32546816 7023 1283457024 134512640 135121179 4287304480 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19251/statm: 7946 7023 333 149 0 7137 0 Current children cumulated CPU time (s) 8.27 Current children cumulated vsize (KiB) 34372 [startup+8.60389 s] /proc/loadavg: 1.07 1.04 1.00 2/35 19253 /proc/meminfo: memFree=503044/1048576 swapFree=0/0 [pid=19239] ppid=19238 vsize=2588 CPUtime=2.15 /proc/19239/stat : 19239 (aspuncud-trendy) S 19238 19239 1511 34817 1511 4202496 623 20390 0 0 0 0 202 13 15 0 1 0 4366087 2650112 297 1283457024 134512640 135304128 4289281200 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/19239/statm: 647 297 251 194 0 34 0 [pid=19251] ppid=19239 vsize=30924 CPUtime=6.32 /proc/19251/stat : 19251 (unclasp) R 19239 19239 1511 34817 1511 4202496 51624 0 0 0 599 33 0 0 25 0 1 0 4366088 31666176 6859 1283457024 134512640 135121179 4287304480 18446744073709551615 134890949 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/19251/statm: 7731 6859 333 149 0 6922 0 Current children cumulated CPU time (s) 8.47 Current children cumulated vsize (KiB) 33512 Child status: 0 Real time (s): 8.67127 CPU time (s): 8.54053 CPU user time (s): 8.0765 CPU system time (s): 0.464029 CPU usage (%): 98.4923 Max. virtual memory (cumulated for all children) (KiB): 61432 getrusage(RUSAGE_CHILDREN,...) data: user time used= 8.0765 system time used= 0.464029 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 75301 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= 1243 involuntary context switches= 1002 runsolver used 0 second user time and 0.012 second system time The end