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/201012081719/cudf2pbo4trendy-1.0/randf61f65.cudf.difficult.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/2010/difficult//randf61f65.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/randf61f65.cudf.difficult.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: 0.96 0.94 0.91 5/36 14542 /proc/meminfo: memFree=33760/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=0 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894806684 2637824 278 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 278 238 194 0 30 0 [pid=14542] ppid=14541 vsize=2580 CPUtime=0.02 /proc/14542/stat : 14542 (cudf_msu32) R 14541 14541 9023 34817 9081 4202496 445 0 0 0 2 0 0 0 25 0 1 0 894806684 2641920 337 1283457024 134512640 136125367 4294384128 18446744073709551615 134717911 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/14542/statm: 645 337 142 394 0 249 0 [startup+0.175604 s] /proc/loadavg: 0.96 0.94 0.91 5/36 14542 /proc/meminfo: memFree=33760/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=0 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894806684 2637824 278 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 278 238 194 0 30 0 [pid=14542] ppid=14541 vsize=9444 CPUtime=0.18 /proc/14542/stat : 14542 (cudf_msu32) R 14541 14541 9023 34817 9081 4202496 2158 0 0 0 18 0 0 0 25 0 1 0 894806684 9670656 2050 1283457024 134512640 136125367 4294384128 18446744073709551615 134717802 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/14542/statm: 2361 2050 142 394 0 1965 0 Current children cumulated CPU time (s) 0.18 Current children cumulated vsize (KiB) 12020 [startup+0.205624 s] /proc/loadavg: 0.96 0.94 0.91 5/36 14542 /proc/meminfo: memFree=33760/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=0 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894806684 2637824 278 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 278 238 194 0 30 0 [pid=14542] ppid=14541 vsize=10576 CPUtime=0.2 /proc/14542/stat : 14542 (cudf_msu32) R 14541 14541 9023 34817 9081 4202496 2445 0 0 0 20 0 0 0 25 0 1 0 894806684 10829824 2337 1283457024 134512640 136125367 4294384128 18446744073709551615 134728322 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/14542/statm: 2644 2337 143 394 0 2248 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 13152 [startup+0.30563 s] /proc/loadavg: 0.96 0.94 0.91 5/36 14542 /proc/meminfo: memFree=33760/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=0 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894806684 2637824 278 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 278 238 194 0 30 0 [pid=14542] ppid=14541 vsize=14140 CPUtime=0.3 /proc/14542/stat : 14542 (cudf_msu32) R 14541 14541 9023 34817 9081 4202496 3353 0 0 0 30 0 0 0 25 0 1 0 894806684 14479360 3245 1283457024 134512640 136125367 4294384128 18446744073709551615 134718199 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/14542/statm: 3535 3245 143 394 0 3139 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 16716 [startup+0.705701 s] /proc/loadavg: 0.96 0.94 0.91 5/36 14542 /proc/meminfo: memFree=33760/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=0 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 382 0 0 0 0 0 0 0 18 0 1 0 894806684 2637824 278 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 278 238 194 0 30 0 [pid=14542] ppid=14541 vsize=26616 CPUtime=0.7 /proc/14542/stat : 14542 (cudf_msu32) R 14541 14541 9023 34817 9081 4202496 6463 0 0 0 68 2 0 0 25 0 1 0 894806684 27254784 6355 1283457024 134512640 136125367 4294384128 18446744073709551615 134984320 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/14542/statm: 6654 6355 153 394 0 6258 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 29192 [startup+1.50585 s] /proc/loadavg: 0.96 0.94 0.91 2/37 14543 /proc/meminfo: memFree=5180/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 Current children cumulated CPU time (s) 1.18 Current children cumulated vsize (KiB) 2576 [startup+3.10615 s] /proc/loadavg: 0.96 0.94 0.91 2/37 14544 /proc/meminfo: memFree=27152/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=16872 CPUtime=1.91 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 5204 0 0 0 139 52 0 0 25 0 1 0 894806803 17276928 3920 1283457024 134512640 135887319 4288029680 18446744073709551615 134637766 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 4218 3920 144 336 0 3880 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 19448 [startup+6.30673 s] /proc/loadavg: 0.96 0.94 0.91 2/37 14544 /proc/meminfo: memFree=14752/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=25308 CPUtime=5.11 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 8700 0 0 0 406 105 0 0 25 0 1 0 894806803 25915392 6072 1283457024 134512640 135887319 4288029680 18446744073709551615 134526502 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 6327 6072 144 336 0 5989 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 27884 [startup+12.708 s] /proc/loadavg: 0.96 0.95 0.91 2/37 14544 /proc/meminfo: memFree=14636/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=25308 CPUtime=11.51 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 8719 0 0 0 1042 109 0 0 25 0 1 0 894806803 25915392 6090 1283457024 134512640 135887319 4288029680 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 6327 6090 144 336 0 5989 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 27884 [startup+25.5117 s] /proc/loadavg: 0.97 0.95 0.91 2/36 14544 /proc/meminfo: memFree=14024/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=26100 CPUtime=24.29 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 8929 0 0 0 2317 112 0 0 25 0 1 0 894806803 26726400 6285 1283457024 134512640 135887319 4288029680 18446744073709551615 134526964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 6525 6285 144 336 0 6187 0 Current children cumulated CPU time (s) 25.47 Current children cumulated vsize (KiB) 28676 [startup+51.1133 s] /proc/loadavg: 0.98 0.95 0.91 2/36 14544 /proc/meminfo: memFree=12288/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=27860 CPUtime=49.83 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 9383 0 0 0 4869 114 0 0 25 0 1 0 894806803 28528640 6696 1283457024 134512640 135887319 4288029680 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 6965 6696 144 336 0 6627 0 Current children cumulated CPU time (s) 51.01 Current children cumulated vsize (KiB) 30436 [startup+102.305 s] /proc/loadavg: 0.99 0.95 0.91 2/36 14544 /proc/meminfo: memFree=8692/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=31432 CPUtime=100.99 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 10371 0 0 0 9981 118 0 0 25 0 1 0 894806803 32186368 7595 1283457024 134512640 135887319 4288029680 18446744073709551615 134603622 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 7858 7595 144 336 0 7520 0 Current children cumulated CPU time (s) 102.17 Current children cumulated vsize (KiB) 34008 [startup+162.308 s] /proc/loadavg: 0.99 0.96 0.91 2/36 14544 /proc/meminfo: memFree=5988/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=35220 CPUtime=160.96 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 11491 0 0 0 15970 126 0 0 25 0 1 0 894806803 36065280 8546 1283457024 134512640 135887319 4288029680 18446744073709551615 134605865 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 8805 8546 144 336 0 8467 0 Current children cumulated CPU time (s) 162.14 Current children cumulated vsize (KiB) 37796 [startup+222.311 s] /proc/loadavg: 0.99 0.97 0.91 2/36 14544 /proc/meminfo: memFree=5392/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=36984 CPUtime=220.92 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 12015 0 0 0 21954 138 0 0 25 0 1 0 894806803 37871616 8980 1283457024 134512640 135887319 4288029680 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 9246 8980 144 336 0 8908 0 Current children cumulated CPU time (s) 222.1 Current children cumulated vsize (KiB) 39560 [startup+282.305 s] /proc/loadavg: 0.99 0.97 0.91 2/36 14544 /proc/meminfo: memFree=5392/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=36984 CPUtime=280.87 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 12016 0 0 0 27937 150 0 0 25 0 1 0 894806803 37871616 8981 1283457024 134512640 135887319 4288029680 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 9246 8981 144 336 0 8908 0 Current children cumulated CPU time (s) 282.05 Current children cumulated vsize (KiB) 39560 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.307 s] /proc/loadavg: 0.99 0.97 0.91 2/36 14544 /proc/meminfo: memFree=5392/1048576 swapFree=2095372/2097144 [pid=14541] ppid=14540 vsize=2576 CPUtime=1.18 /proc/14541/stat : 14541 (cudf2pbo4trendy) S 14540 14541 9023 34817 9081 4202496 402 8383 0 0 0 0 100 18 20 0 1 0 894806684 2637824 281 1283457024 134512640 135304128 4287378144 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/14541/statm: 644 281 241 194 0 30 0 [pid=14544] ppid=14541 vsize=36984 CPUtime=288.86 /proc/14544/stat : 14544 (bmo-pblex32) R 14541 14541 9023 34817 9081 4202496 12016 0 0 0 28736 150 0 0 25 0 1 0 894806803 37871616 8981 1283457024 134512640 135887319 4288029680 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/14544/statm: 9246 8981 144 336 0 8908 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 39560 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.367 CPU time (s): 290.106 CPU user time (s): 288.398 CPU system time (s): 1.70811 CPU usage (%): 99.91 Max. virtual memory (cumulated for all children) (KiB): 39560 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.398 system time used= 1.70811 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 22586 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= 7 involuntary context switches= 4816 runsolver used 0 second user time and 0 second system time The end