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/201012091704/aspcud-1.3/1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aspcud-1.3 /home/misc2010/data/2010/debian-dudf//1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf /home/misc2010/tmp/201012091704/aspcud-1.3/1dcce248-4bb4-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.result -changed,-notuptodate,-removed,-new 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.08 0.66 0.52 5/39 2704 /proc/meminfo: memFree=377392/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2588 CPUtime=0 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 375 0 0 0 0 0 0 0 18 0 1 0 900740688 2650112 282 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 0 4 65536 18446744071564457842 0 0 17 0 0 0 0 /proc/2702/statm: 647 282 237 194 0 33 0 [pid=2703] ppid=2702 vsize=2588 CPUtime=0 /proc/2703/stat : 2703 (aspcud-1.3) R 2702 2702 25521 34816 2180 4202560 105 0 0 0 0 0 0 0 25 0 1 0 900740688 2650112 128 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/2703/statm: 647 128 82 194 0 33 0 [pid=2704] ppid=2703 vsize=2588 CPUtime=0 /proc/2704/stat : 2704 (aspcud-1.3) R 2703 2702 25521 34816 2180 4202560 0 0 0 0 0 0 0 0 25 0 1 0 900740688 2650112 46 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65538 0 65538 0 0 0 17 0 0 0 0 /proc/2704/statm: 647 46 0 194 0 33 0 [startup+0.192679 s] /proc/loadavg: 1.08 0.66 0.52 5/39 2704 /proc/meminfo: memFree=377392/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=0 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 574 1505 0 0 0 0 0 0 25 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.20269 s] /proc/loadavg: 1.08 0.66 0.52 5/39 2704 /proc/meminfo: memFree=377392/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=0 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 574 1505 0 0 0 0 0 0 25 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.312708 s] /proc/loadavg: 1.08 0.66 0.52 5/39 2704 /proc/meminfo: memFree=377392/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=0 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 574 1505 0 0 0 0 0 0 25 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.712798 s] /proc/loadavg: 1.08 0.66 0.52 5/39 2704 /proc/meminfo: memFree=377392/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=0 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 574 1505 0 0 0 0 0 0 25 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.51299 s] /proc/loadavg: 1.07 0.67 0.52 2/41 2713 /proc/meminfo: memFree=335452/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=0 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 574 1505 0 0 0 0 0 0 25 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=6308 CPUtime=0.01 /proc/2711/stat : 2711 (clasp) S 2702 2702 25521 34816 2180 4202496 1512 0 0 0 0 1 0 0 18 0 1 0 900740689 6459392 1298 1283457024 134512640 136223643 4293423232 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/2711/statm: 1577 1298 174 418 0 1157 0 [pid=2712] ppid=2702 vsize=9344 CPUtime=0.22 /proc/2712/stat : 2712 (gringo) R 2702 2702 25521 34816 2180 4202496 2453 0 0 0 22 0 0 0 18 0 1 0 900740689 9568256 1546 1283457024 134512640 136959103 4288826528 18446744073709551615 134697081 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2712/statm: 2336 1546 247 598 0 1735 0 [pid=2713] ppid=2702 vsize=40868 CPUtime=1.27 /proc/2713/stat : 2713 (cudf2lp) R 2702 2702 25521 34816 2180 4202496 13293 0 0 0 123 4 0 0 25 0 1 0 900740689 41848832 10024 1283457024 134512640 135749571 4290862736 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/2713/statm: 10217 10024 132 302 0 9913 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 59116 [startup+3.11337 s] /proc/loadavg: 1.07 0.67 0.52 3/41 2713 /proc/meminfo: memFree=306808/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=1.54 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 14801 0 0 0 0 150 4 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=33204 CPUtime=0.12 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 9385 0 0 0 10 2 0 0 18 0 1 0 900740689 34000896 7885 1283457024 134512640 136223643 4293423232 18446744073709551615 135666734 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 8301 7885 174 418 0 7881 0 [pid=2712] ppid=2702 vsize=53420 CPUtime=1.43 /proc/2712/stat : 2712 (gringo) R 2702 2702 25521 34816 2180 4202496 15794 0 0 0 141 2 0 0 18 0 1 0 900740689 54702080 11033 1283457024 134512640 136959103 4288826528 18446744073709551615 134696613 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2712/statm: 13355 11033 256 598 0 12754 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 89220 [startup+6.30444 s] /proc/loadavg: 1.07 0.67 0.52 2/39 2713 /proc/meminfo: memFree=323456/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=58696 CPUtime=2.7 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 17118 0 0 0 266 4 0 0 22 0 1 0 900740689 60104704 13551 1283457024 134512640 136223643 4293423232 18446744073709551615 134650502 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 14674 13551 223 418 0 14254 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 61292 [startup+12.7068 s] /proc/loadavg: 1.06 0.68 0.53 2/39 2713 /proc/meminfo: memFree=309196/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=75476 CPUtime=9.1 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 21309 0 0 0 904 6 0 0 25 0 1 0 900740689 77287424 17742 1283457024 134512640 136223643 4293423232 18446744073709551615 134931000 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 18869 17742 225 418 0 18449 0 Current children cumulated CPU time (s) 12.68 Current children cumulated vsize (KiB) 78072 [startup+25.5107 s] /proc/loadavg: 1.05 0.69 0.53 2/39 2713 /proc/meminfo: memFree=258852/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=125080 CPUtime=21.89 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 33693 0 0 0 2179 10 0 0 25 0 1 0 900740689 128081920 30126 1283457024 134512640 136223643 4293423232 18446744073709551615 134664671 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 31270 30126 225 418 0 30850 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 127676 [startup+51.1089 s] /proc/loadavg: 1.03 0.71 0.55 2/39 2713 /proc/meminfo: memFree=242484/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=139976 CPUtime=47.46 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 37424 0 0 0 4733 13 0 0 25 0 1 0 900740689 143335424 33857 1283457024 134512640 136223643 4293423232 18446744073709551615 134631201 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 34994 33857 225 418 0 34574 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 142572 [startup+102.305 s] /proc/loadavg: 1.01 0.76 0.57 2/39 2713 /proc/meminfo: memFree=242484/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=139976 CPUtime=98.6 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 37431 0 0 0 9847 13 0 0 25 0 1 0 900740689 143335424 33864 1283457024 134512640 136223643 4293423232 18446744073709551615 134928869 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 34994 33864 225 418 0 34574 0 Current children cumulated CPU time (s) 102.18 Current children cumulated vsize (KiB) 142572 [startup+162.311 s] /proc/loadavg: 1.00 0.80 0.59 2/39 2713 /proc/meminfo: memFree=242484/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=139976 CPUtime=158.5 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 37431 0 0 0 15837 13 0 0 25 0 1 0 900740689 143335424 33864 1283457024 134512640 136223643 4293423232 18446744073709551615 134924387 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 34994 33864 225 418 0 34574 0 Current children cumulated CPU time (s) 162.08 Current children cumulated vsize (KiB) 142572 [startup+222.311 s] /proc/loadavg: 1.00 0.83 0.61 2/39 2713 /proc/meminfo: memFree=242360/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=139976 CPUtime=218.47 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 37431 0 0 0 21832 15 0 0 25 0 1 0 900740689 143335424 33864 1283457024 134512640 136223643 4293423232 18446744073709551615 134929646 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 34994 33864 225 418 0 34574 0 Current children cumulated CPU time (s) 222.05 Current children cumulated vsize (KiB) 142572 [startup+282.31 s] /proc/loadavg: 1.00 0.86 0.64 2/39 2713 /proc/meminfo: memFree=242360/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=139976 CPUtime=278.42 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 37431 0 0 0 27826 16 0 0 25 0 1 0 900740689 143335424 33864 1283457024 134512640 136223643 4293423232 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 34994 33864 225 418 0 34574 0 Current children cumulated CPU time (s) 282 Current children cumulated vsize (KiB) 142572 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.312 s] /proc/loadavg: 1.00 0.86 0.64 2/39 2713 /proc/meminfo: memFree=242360/1048576 swapFree=2095372/2097144 [pid=2702] ppid=2701 vsize=2596 CPUtime=3.58 /proc/2702/stat : 2702 (aspcud-1.3) S 2701 2702 25521 34816 2180 4202496 575 33437 0 0 0 0 346 12 18 0 1 0 900740688 2658304 300 1283457024 134512640 135304128 4287841040 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/2702/statm: 649 300 253 194 0 35 0 [pid=2711] ppid=2702 vsize=139976 CPUtime=286.42 /proc/2711/stat : 2711 (clasp) R 2702 2702 25521 34816 2180 4202496 37431 0 0 0 28626 16 0 0 25 0 1 0 900740689 143335424 33864 1283457024 134512640 136223643 4293423232 18446744073709551615 134711295 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/2711/statm: 34994 33864 225 418 0 34574 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 142572 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.344 CPU time (s): 290.058 CPU user time (s): 289.73 CPU system time (s): 0.32802 CPU usage (%): 99.9014 Max. virtual memory (cumulated for all children) (KiB): 142572 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.73 system time used= 0.32802 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 74059 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= 2917 involuntary context switches= 5719 runsolver used 0 second user time and 0.012 second system time The end