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/201108251442/aspuncud-paranoid-1.3/301cbe92-a79c-11e0-9181-00163e1e087d.cudf.dudf-real.log.runsolver ./aspuncud-paranoid-1.3 /home/misc2010/data/2011/dudf-real//301cbe92-a79c-11e0-9181-00163e1e087d.cudf /home/misc2010/tmp/201108251442/aspuncud-paranoid-1.3/301cbe92-a79c-11e0-9181-00163e1e087d.cudf.dudf-real.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.49 1.13 1.04 3/34 16729 /proc/meminfo: memFree=294544/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2588 CPUtime=0 /proc/16728/stat : 16728 (aspuncud-parano) R 16727 16728 4778 34817 4778 4202496 366 0 0 0 0 0 0 0 25 0 1 0 10975157 2650112 280 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/16728/statm: 647 280 234 194 0 34 0 [pid=16729] ppid=16728 vsize=2588 CPUtime=0 /proc/16729/stat : 16729 (aspuncud-parano) R 16728 16728 4778 34817 4778 4202560 0 0 0 0 0 0 0 0 25 0 1 0 10975158 2650112 46 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0 /proc/16729/statm: 647 46 0 194 0 34 0 [startup+0.183408 s] /proc/loadavg: 1.49 1.13 1.04 3/34 16729 /proc/meminfo: memFree=294544/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=0.01 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 2938 0 0 0 0 1 0 25 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.213412 s] /proc/loadavg: 1.49 1.13 1.04 3/34 16729 /proc/meminfo: memFree=294544/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=0.01 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 2938 0 0 0 0 1 0 25 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.303434 s] /proc/loadavg: 1.49 1.13 1.04 3/34 16729 /proc/meminfo: memFree=294544/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=0.01 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 2938 0 0 0 0 1 0 25 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+0.70349 s] /proc/loadavg: 1.49 1.13 1.04 3/34 16729 /proc/meminfo: memFree=294544/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=0.01 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 2938 0 0 0 0 1 0 25 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 Current children cumulated CPU time (s) 0.01 Current children cumulated vsize (KiB) 2592 [startup+1.50362 s] /proc/loadavg: 1.45 1.13 1.04 2/37 16745 /proc/meminfo: memFree=272800/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=0.01 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 2938 0 0 0 0 1 0 25 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 [pid=16743] ppid=16728 vsize=3444 CPUtime=0 /proc/16743/stat : 16743 (unclasp) S 16728 16728 4778 34817 4778 4202496 407 0 0 0 0 0 0 0 25 0 1 0 10975159 3526656 272 1283457024 134512640 135121179 4294558208 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16743/statm: 861 272 240 149 0 52 0 [pid=16744] ppid=16728 vsize=2692 CPUtime=0 /proc/16744/stat : 16744 (gringo) S 16728 16728 4778 34817 4778 4202496 409 0 0 0 0 0 0 0 25 0 1 0 10975159 2756608 281 1283457024 134512640 137056543 4292276064 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16744/statm: 673 281 252 622 0 48 0 [pid=16745] ppid=16728 vsize=36496 CPUtime=1.48 /proc/16745/stat : 16745 (cudf2lp) R 16728 16728 4778 34817 4778 4202496 10425 0 0 0 145 3 0 0 25 0 1 0 10975159 37371904 8726 1283457024 134512640 135786343 4290907792 18446744073709551615 134548162 0 0 6 0 0 0 0 17 0 0 0 0 /proc/16745/statm: 9124 8726 133 311 0 8811 0 Current children cumulated CPU time (s) 1.49 Current children cumulated vsize (KiB) 45224 Solver just ended. Dumping a history of the last processes samples [startup+1.61364 s] /proc/loadavg: 1.45 1.13 1.04 2/37 16745 /proc/meminfo: memFree=272800/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=0.01 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 2938 0 0 0 0 1 0 25 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 [pid=16743] ppid=16728 vsize=3444 CPUtime=0 /proc/16743/stat : 16743 (unclasp) S 16728 16728 4778 34817 4778 4202496 407 0 0 0 0 0 0 0 25 0 1 0 10975159 3526656 272 1283457024 134512640 135121179 4294558208 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16743/statm: 861 272 240 149 0 52 0 [pid=16744] ppid=16728 vsize=2692 CPUtime=0 /proc/16744/stat : 16744 (gringo) S 16728 16728 4778 34817 4778 4202496 409 0 0 0 0 0 0 0 25 0 1 0 10975159 2756608 281 1283457024 134512640 137056543 4292276064 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/16744/statm: 673 281 252 622 0 48 0 [pid=16745] ppid=16728 vsize=42832 CPUtime=1.59 /proc/16745/stat : 16745 (cudf2lp) R 16728 16728 4778 34817 4778 4202496 12024 0 0 0 154 5 0 0 25 0 1 0 10975159 43859968 10325 1283457024 134512640 135786343 4290907792 18446744073709551615 134553391 0 0 6 0 0 0 0 17 0 0 0 0 /proc/16745/statm: 10708 10325 133 311 0 10395 0 Current children cumulated CPU time (s) 1.6 Current children cumulated vsize (KiB) 51560 [startup+2.40376 s] /proc/loadavg: 1.45 1.13 1.04 2/37 16745 /proc/meminfo: memFree=240436/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=1.87 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 15437 0 0 0 0 180 7 18 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 [pid=16743] ppid=16728 vsize=13644 CPUtime=0.1 /proc/16743/stat : 16743 (unclasp) R 16728 16728 4778 34817 4778 4202496 3245 0 0 0 7 3 0 0 18 0 1 0 10975159 13971456 2815 1283457024 134512640 135121179 4294558208 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16743/statm: 3411 2815 277 149 0 2602 0 [pid=16744] ppid=16728 vsize=19508 CPUtime=0.41 /proc/16744/stat : 16744 (gringo) R 16728 16728 4778 34817 4778 4202496 5432 0 0 0 40 1 0 0 18 0 1 0 10975159 19976192 3485 1283457024 134512640 137056543 4292276064 18446744073709551615 134753316 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16744/statm: 4877 3485 268 622 0 4252 0 Current children cumulated CPU time (s) 2.38 Current children cumulated vsize (KiB) 35744 [startup+2.80384 s] /proc/loadavg: 1.45 1.13 1.04 2/37 16745 /proc/meminfo: memFree=240436/1048576 swapFree=0/0 [pid=16728] ppid=16727 vsize=2592 CPUtime=2.5 /proc/16728/stat : 16728 (aspuncud-parano) S 16727 16728 4778 34817 4778 4202496 660 22403 0 0 0 0 242 8 16 0 1 0 10975157 2654208 298 1283457024 134512640 135304128 4286919216 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/16728/statm: 648 298 251 194 0 35 0 [pid=16743] ppid=16728 vsize=23800 CPUtime=0.29 /proc/16743/stat : 16743 (unclasp) R 16728 16728 4778 34817 4778 4202496 6075 0 0 0 26 3 0 0 18 0 1 0 10975159 24371200 5433 1283457024 134512640 135121179 4294558208 18446744073709551615 4158416243 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/16743/statm: 5950 5433 320 149 0 5141 0 Current children cumulated CPU time (s) 2.79 Current children cumulated vsize (KiB) 26392 Child status: 0 Real time (s): 2.86608 CPU time (s): 2.86018 CPU user time (s): 2.72017 CPU system time (s): 0.140008 CPU usage (%): 99.7939 Max. virtual memory (cumulated for all children) (KiB): 64748 getrusage(RUSAGE_CHILDREN,...) data: user time used= 2.72017 system time used= 0.140008 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 31515 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= 1110 involuntary context switches= 825 runsolver used 0.008 second user time and 0 second system time The end