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/201012070034/aspcud-trendy-1.3/rand8cc693.cudf.impossible.log.runsolver ./aspcud-trendy-1.3 /home/misc2010/data/2010/impossible//rand8cc693.cudf /home/misc2010/tmp/201012070034/aspcud-trendy-1.3/rand8cc693.cudf.impossible.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.08 1.11 1.04 1/44 32172 /proc/meminfo: memFree=691056/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=3024 CPUtime=0 /proc/32172/stat : 32172 (runsolver) D 32171 32172 4159 34819 4229 4202560 72 0 0 0 0 0 0 0 25 0 1 0 884423851 3096576 93 1283457024 134512640 134586868 4288850816 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0 /proc/32172/statm: 756 93 62 19 0 54 0 [startup+0.179165 s] /proc/loadavg: 1.08 1.11 1.04 1/44 32172 /proc/meminfo: memFree=691056/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=0 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 2215 0 3 0 0 0 0 25 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.207163 s] /proc/loadavg: 1.08 1.11 1.04 1/44 32172 /proc/meminfo: memFree=691056/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=0 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 2215 0 3 0 0 0 0 25 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.30719 s] /proc/loadavg: 1.08 1.11 1.04 1/44 32172 /proc/meminfo: memFree=691056/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=0 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 2215 0 3 0 0 0 0 25 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+0.707237 s] /proc/loadavg: 1.08 1.11 1.04 1/44 32172 /proc/meminfo: memFree=691056/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=0 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 2215 0 3 0 0 0 0 25 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 Current children cumulated CPU time (s) 0 Current children cumulated vsize (KiB) 2596 [startup+1.50733 s] /proc/loadavg: 1.08 1.11 1.04 2/48 32186 /proc/meminfo: memFree=652868/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=0 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 2215 0 3 0 0 0 0 25 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=1868 CPUtime=0 /proc/32184/stat : 32184 (clasp) S 32172 32172 4159 34819 4229 4202496 269 0 15 0 0 0 0 0 24 0 1 0 884423855 1912832 153 1283457024 134512640 136223643 4293574720 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/32184/statm: 467 153 138 418 0 47 0 [pid=32185] ppid=32172 vsize=2604 CPUtime=0 /proc/32185/stat : 32185 (gringo) S 32172 32172 4159 34819 4229 4202496 384 0 22 0 0 0 0 0 23 0 1 0 884423855 2666496 276 1283457024 134512640 136959103 4293304704 18446744073709551615 135656590 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/32185/statm: 651 276 247 598 0 50 0 [pid=32186] ppid=32172 vsize=51664 CPUtime=1.29 /proc/32186/stat : 32186 (cudf2lp) R 32172 32172 4159 34819 4229 4202496 14247 0 14 0 124 5 0 0 25 0 1 0 884423855 52903936 12109 1283457024 134512640 135749571 4293577648 18446744073709551615 135198597 0 0 6 0 0 0 0 17 0 0 0 0 /proc/32186/statm: 12916 12109 127 302 0 12612 0 Current children cumulated CPU time (s) 1.29 Current children cumulated vsize (KiB) 58732 [startup+3.10798 s] /proc/loadavg: 1.08 1.11 1.04 3/48 32186 /proc/meminfo: memFree=616356/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=0 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 2215 0 3 0 0 0 0 25 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=18860 CPUtime=0.08 /proc/32184/stat : 32184 (clasp) S 32172 32172 4159 34819 4229 4202496 5192 0 18 0 7 1 0 0 18 0 1 0 884423855 19312640 4421 1283457024 134512640 136223643 4293574720 18446744073709551615 135666734 0 0 6 16384 18446744071564457842 0 0 17 0 0 0 0 /proc/32184/statm: 4715 4421 174 418 0 4295 0 [pid=32185] ppid=32172 vsize=28428 CPUtime=0.87 /proc/32185/stat : 32185 (gringo) R 32172 32172 4159 34819 4229 4202496 8692 0 22 0 85 2 0 0 18 0 1 0 884423855 29110272 5002 1283457024 134512640 136959103 4293304704 18446744073709551615 134769792 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32185/statm: 7107 5002 247 598 0 6506 0 [pid=32186] ppid=32172 vsize=62348 CPUtime=1.93 /proc/32186/stat : 32186 (cudf2lp) R 32172 32172 4159 34819 4229 4202496 18986 0 14 0 186 7 0 0 25 0 1 0 884423855 63844352 15186 1283457024 134512640 135749571 4293577648 18446744073709551615 135237662 0 0 6 0 0 0 0 17 0 0 0 0 /proc/32186/statm: 15587 15186 129 302 0 15283 0 Current children cumulated CPU time (s) 2.88 Current children cumulated vsize (KiB) 112232 [startup+6.31295 s] /proc/loadavg: 1.15 1.12 1.05 2/46 32186 /proc/meminfo: memFree=633316/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=70972 CPUtime=1.43 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 20515 0 19 0 138 5 0 0 19 0 1 0 884423855 72675328 16369 1283457024 134512640 136223643 4293574720 18446744073709551615 134867480 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 17743 16369 214 418 0 17323 0 Current children cumulated CPU time (s) 6.07 Current children cumulated vsize (KiB) 73568 [startup+12.7045 s] /proc/loadavg: 1.14 1.12 1.05 2/46 32186 /proc/meminfo: memFree=621536/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=69756 CPUtime=7.83 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 20557 0 19 0 778 5 0 0 25 0 1 0 884423855 71430144 16157 1283457024 134512640 136223643 4293574720 18446744073709551615 134931442 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 17439 16157 225 418 0 17019 0 Current children cumulated CPU time (s) 12.47 Current children cumulated vsize (KiB) 72352 [startup+25.5077 s] /proc/loadavg: 1.11 1.11 1.04 2/46 32186 /proc/meminfo: memFree=614344/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=78204 CPUtime=20.61 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 22656 0 19 0 2053 8 0 0 25 0 1 0 884423855 80080896 18256 1283457024 134512640 136223643 4293574720 18446744073709551615 134924244 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 19551 18256 225 418 0 19131 0 Current children cumulated CPU time (s) 25.25 Current children cumulated vsize (KiB) 80800 [startup+51.1159 s] /proc/loadavg: 1.07 1.10 1.04 2/46 32186 /proc/meminfo: memFree=569828/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=123296 CPUtime=46.21 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 33903 0 19 0 4605 16 0 0 25 0 1 0 884423855 126255104 29503 1283457024 134512640 136223643 4293574720 18446744073709551615 134650794 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 30824 29503 225 418 0 30404 0 Current children cumulated CPU time (s) 50.85 Current children cumulated vsize (KiB) 125892 [startup+102.312 s] /proc/loadavg: 1.03 1.09 1.04 2/46 32186 /proc/meminfo: memFree=545648/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=145968 CPUtime=97.35 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 39539 0 19 0 9715 20 0 0 25 0 1 0 884423855 149471232 35139 1283457024 134512640 136223643 4293574720 18446744073709551615 134929251 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 36492 35139 225 418 0 36072 0 Current children cumulated CPU time (s) 101.99 Current children cumulated vsize (KiB) 148564 [startup+162.311 s] /proc/loadavg: 1.01 1.07 1.03 2/46 32186 /proc/meminfo: memFree=507084/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=184300 CPUtime=157.32 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 49127 0 19 0 15698 34 0 0 25 0 1 0 884423855 188723200 44727 1283457024 134512640 136223643 4293574720 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 46075 44727 225 418 0 45655 0 Current children cumulated CPU time (s) 161.96 Current children cumulated vsize (KiB) 186896 [startup+222.313 s] /proc/loadavg: 1.00 1.05 1.03 2/46 32186 /proc/meminfo: memFree=505596/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=185752 CPUtime=217.31 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 49505 0 19 0 21695 36 0 0 25 0 1 0 884423855 190210048 45105 1283457024 134512640 136223643 4293574720 18446744073709551615 134929006 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 46438 45105 225 418 0 46018 0 Current children cumulated CPU time (s) 221.95 Current children cumulated vsize (KiB) 188348 [startup+282.313 s] /proc/loadavg: 1.00 1.04 1.02 2/46 32186 /proc/meminfo: memFree=494188/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=196952 CPUtime=277.28 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 52309 0 19 0 27686 42 0 0 25 0 1 0 884423855 201678848 47909 1283457024 134512640 136223643 4293574720 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 49238 47909 225 418 0 48818 0 Current children cumulated CPU time (s) 281.92 Current children cumulated vsize (KiB) 199548 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.405 s] /proc/loadavg: 1.00 1.04 1.02 2/46 32186 /proc/meminfo: memFree=494188/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=196952 CPUtime=285.37 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 52314 0 19 0 28495 42 0 0 25 0 1 0 884423855 201678848 47914 1283457024 134512640 136223643 4293574720 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 49238 47914 225 418 0 48818 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 199548 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.405 s] /proc/loadavg: 1.00 1.04 1.02 2/46 32186 /proc/meminfo: memFree=494188/1048576 swapFree=2077628/2097144 [pid=32172] ppid=32171 vsize=2596 CPUtime=4.64 /proc/32172/stat : 32172 (aspcud-trendy-1) S 32171 32172 4159 34819 4229 4202496 614 46916 0 40 0 0 447 17 18 0 1 0 884423851 2658304 299 1283457024 134512640 135304128 4290903616 18446744073709551615 4294960130 0 65536 4 1132560123 18446744071564329979 0 0 17 0 0 0 0 /proc/32172/statm: 649 299 253 194 0 35 0 [pid=32184] ppid=32172 vsize=196952 CPUtime=285.37 /proc/32184/stat : 32184 (clasp) R 32172 32172 4159 34819 4229 4202496 52314 0 19 0 28495 42 0 0 25 0 1 0 884423855 201678848 47914 1283457024 134512640 136223643 4293574720 18446744073709551615 134931099 0 0 6 16384 0 0 0 17 0 0 0 0 /proc/32184/statm: 49238 47914 225 418 0 48818 0 Current children cumulated CPU time (s) 290.01 Current children cumulated vsize (KiB) 199548 Child status: 0 Real time (s): 290.461 CPU time (s): 290.046 CPU user time (s): 289.43 CPU system time (s): 0.616038 CPU usage (%): 99.8573 Max. virtual memory (cumulated for all children) (KiB): 199548 getrusage(RUSAGE_CHILDREN,...) data: user time used= 289.43 system time used= 0.616038 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 102450 page faults= 61 swaps= 0 block input operations= 0 block output operations= 0 messages sent= 0 messages received= 0 signals received= 0 voluntary context switches= 4147 involuntary context switches= 6941 runsolver used 0 second user time and 0.004 second system time The end