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/201108300820/aspuncud-user-1.0/412959c6-e965-11de-8ebf-00163e6585dd.cudf.dudf-real.log.runsolver ./aspuncud-user-1.0 /home/misc2010/data/2011/dudf-real//412959c6-e965-11de-8ebf-00163e6585dd.cudf /home/misc2010/tmp/201108300820/aspuncud-user-1.0/412959c6-e965-11de-8ebf-00163e6585dd.cudf.dudf-real.result +sum(installedsize) 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.25 1.10 1.02 2/37 8143 /proc/meminfo: memFree=949904/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=3016 CPUtime=0 /proc/8143/stat : 8143 (runsolver) D 8142 8143 2160 34817 2160 4202560 72 0 0 0 0 0 0 0 25 0 1 0 54008335 3088384 93 1283457024 134512640 134586868 4289084256 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/8143/statm: 754 93 62 19 0 53 0 [startup+0.207326 s] /proc/loadavg: 1.25 1.10 1.02 2/37 8143 /proc/meminfo: memFree=949904/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=0 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.307297 s] /proc/loadavg: 1.25 1.10 1.02 2/37 8143 /proc/meminfo: memFree=949904/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=0 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.407312 s] /proc/loadavg: 1.25 1.10 1.02 2/37 8143 /proc/meminfo: memFree=949904/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=0 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.707354 s] /proc/loadavg: 1.25 1.10 1.02 2/37 8143 /proc/meminfo: memFree=949904/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=0 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50745 s] /proc/loadavg: 1.31 1.11 1.03 3/42 8155 /proc/meminfo: memFree=918256/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=0 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 1516 0 3 0 0 0 0 25 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=9472 CPUtime=0.04 /proc/8152/stat : 8152 (unclasp) S 8143 8143 2160 34817 2160 4202496 2114 0 6 0 4 0 0 0 18 0 1 0 54008340 9699328 1780 1283457024 134512640 135121179 4289999072 18446744073709551615 4294960130 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/8152/statm: 2368 1780 275 149 0 1559 0 [pid=8153] ppid=8143 vsize=11656 CPUtime=0.32 /proc/8153/stat : 8153 (gringo) R 8143 8143 2160 34817 2160 4202496 3070 0 23 0 30 2 0 0 18 0 1 0 54008340 11935744 2142 1283457024 134512640 137056543 4289998224 18446744073709551615 134745759 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8153/statm: 2914 2142 253 622 0 2289 0 [pid=8154] ppid=8143 vsize=24676 CPUtime=0.94 /proc/8154/stat : 8154 (cudf2lp) R 8143 8143 2160 34817 2160 4202496 7467 0 15 0 90 4 0 0 25 0 1 0 54008340 25268224 5989 1283457024 134512640 135786343 4293360240 18446744073709551615 135258574 0 0 6 0 0 0 0 17 0 0 0 0 /proc/8154/statm: 6169 5989 139 311 0 5856 0 Current children cumulated CPU time (s) 1.3 Current children cumulated vsize (KiB) 48400 [startup+3.10766 s] /proc/loadavg: 1.31 1.11 1.03 4/42 8155 /proc/meminfo: memFree=883536/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=1.24 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 8986 0 18 0 0 119 5 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=35780 CPUtime=0.15 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 9686 0 6 0 11 4 0 0 18 0 1 0 54008340 36638720 8188 1283457024 134512640 135121179 4289999072 18446744073709551615 4294960130 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 8945 8188 277 149 0 8136 0 [pid=8153] ppid=8143 vsize=46236 CPUtime=1.49 /proc/8153/stat : 8153 (gringo) R 8143 8143 2160 34817 2160 4202496 14155 0 23 0 141 8 0 0 18 0 1 0 54008340 47345664 9762 1283457024 134512640 137056543 4289998224 18446744073709551615 136323462 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8153/statm: 11559 9762 268 622 0 10934 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 84612 [startup+6.30995 s] /proc/loadavg: 1.28 1.11 1.03 2/40 8155 /proc/meminfo: memFree=884684/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=66112 CPUtime=2.49 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 30279 0 7 0 243 6 0 0 21 0 1 0 54008340 67698688 15260 1283457024 134512640 135121179 4289999072 18446744073709551615 134990484 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16528 15260 321 149 0 15719 0 Current children cumulated CPU time (s) 6.09 Current children cumulated vsize (KiB) 68708 [startup+12.7124 s] /proc/loadavg: 1.26 1.11 1.03 2/40 8156 /proc/meminfo: memFree=884684/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=66472 CPUtime=8.89 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 67393 0 7 0 867 22 0 0 25 0 1 0 54008340 68067328 15352 1283457024 134512640 135121179 4289999072 18446744073709551615 134734310 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16618 15352 321 149 0 15809 0 Current children cumulated CPU time (s) 12.49 Current children cumulated vsize (KiB) 69068 [startup+25.5093 s] /proc/loadavg: 1.20 1.10 1.02 2/40 8157 /proc/meminfo: memFree=884560/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=67260 CPUtime=21.68 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 133726 0 7 0 2108 60 0 0 25 0 1 0 54008340 68874240 15512 1283457024 134512640 135121179 4289999072 18446744073709551615 4158434070 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16815 15512 321 149 0 16006 0 Current children cumulated CPU time (s) 25.28 Current children cumulated vsize (KiB) 69856 [startup+51.1087 s] /proc/loadavg: 1.13 1.09 1.02 2/40 8160 /proc/meminfo: memFree=886048/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=66224 CPUtime=47.26 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 330315 0 7 0 4572 154 0 0 25 0 1 0 54008340 67813376 15345 1283457024 134512640 135121179 4289999072 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16556 15345 321 149 0 15747 0 Current children cumulated CPU time (s) 50.86 Current children cumulated vsize (KiB) 68820 [startup+102.307 s] /proc/loadavg: 1.06 1.08 1.02 2/39 8164 /proc/meminfo: memFree=885704/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=64736 CPUtime=98.4 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 940343 0 7 0 9422 418 0 0 25 0 1 0 54008340 66289664 14954 1283457024 134512640 135121179 4289999072 18446744073709551615 134713296 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16184 14954 321 149 0 15375 0 Current children cumulated CPU time (s) 102 Current children cumulated vsize (KiB) 67332 [startup+162.315 s] /proc/loadavg: 1.02 1.06 1.01 2/38 8164 /proc/meminfo: memFree=885340/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=67140 CPUtime=158.36 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 1649337 0 7 0 15121 715 0 0 25 0 1 0 54008340 68751360 15572 1283457024 134512640 135121179 4289999072 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16785 15572 321 149 0 15976 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 69736 [startup+222.309 s] /proc/loadavg: 1.00 1.05 1.00 2/38 8164 /proc/meminfo: memFree=884100/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=65656 CPUtime=218.26 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 2328894 0 7 0 20816 1010 0 0 25 0 1 0 54008340 67231744 15231 1283457024 134512640 135121179 4289999072 18446744073709551615 134891059 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16414 15231 321 149 0 15605 0 Current children cumulated CPU time (s) 221.86 Current children cumulated vsize (KiB) 68252 [startup+282.309 s] /proc/loadavg: 1.00 1.04 1.00 2/38 8164 /proc/meminfo: memFree=884348/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=66644 CPUtime=278.2 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 3014820 0 7 0 26544 1276 0 0 25 0 1 0 54008340 68243456 15511 1283457024 134512640 135121179 4289999072 18446744073709551615 134980996 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16661 15511 321 149 0 15852 0 Current children cumulated CPU time (s) 281.8 Current children cumulated vsize (KiB) 69240 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.511 s] /proc/loadavg: 1.00 1.03 1.00 2/38 8164 /proc/meminfo: memFree=882860/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=67196 CPUtime=286.4 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 3109393 0 7 0 27319 1321 0 0 25 0 1 0 54008340 68808704 15654 1283457024 134512640 135121179 4289999072 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16799 15654 321 149 0 15990 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 69792 Sending User defined signal 1 to process tree (bottom up) Sleeping 10 seconds Solver just ended. Dumping a history of the last processes samples [startup+290.511 s] /proc/loadavg: 1.00 1.03 1.00 2/38 8164 /proc/meminfo: memFree=882860/1048576 swapFree=0/0 [pid=8143] ppid=8142 vsize=2596 CPUtime=3.6 /proc/8143/stat : 8143 (aspuncud-user-1) S 8142 8143 2160 34817 2160 4202496 573 30976 0 41 0 0 344 16 18 0 1 0 54008335 2658304 298 1283457024 134512640 135304128 4292847568 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/8143/statm: 649 298 251 194 0 36 0 [pid=8152] ppid=8143 vsize=67196 CPUtime=286.4 /proc/8152/stat : 8152 (unclasp) R 8143 8143 2160 34817 2160 4202496 3109393 0 7 0 27319 1321 0 0 25 0 1 0 54008340 68808704 15654 1283457024 134512640 135121179 4289999072 18446744073709551615 134980988 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/8152/statm: 16799 15654 321 149 0 15990 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 69792 Child status: 0 Real time (s): 290.547 CPU time (s): 290.034 CPU user time (s): 276.661 CPU system time (s): 13.3728 CPU usage (%): 99.8236 Max. virtual memory (cumulated for all children) (KiB): 122620 getrusage(RUSAGE_CHILDREN,...) data: user time used= 276.661 system time used= 13.3728 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 3143332 page faults= 50 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 4053 involuntary context switches= 6665 runsolver used 0 second user time and 0 second system time The end