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/cudf2pbo4paranoid-1.0/large3.cudf.cudf_set.log.runsolver ./cudf2pbo4paranoid-1.0 /home/misc2010/data/2010/cudf_set//large3.cudf /home/misc2010/tmp/201012081719/cudf2pbo4paranoid-1.0/large3.cudf.cudf_set.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.90 0.94 0.90 5/39 11161 /proc/meminfo: memFree=37532/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.01 /proc/11160/stat : 11160 (cudf2pbo4parano) R 11159 11160 9023 34817 9081 4202496 365 0 0 0 1 0 0 0 25 0 1 0 893412963 2633728 279 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/11160/statm: 643 279 238 194 0 29 0 [pid=11161] ppid=11160 vsize=2572 CPUtime=0 /proc/11161/stat : 11161 (cudf2pbo4parano) R 11160 11160 9023 34817 9081 4202560 0 0 0 0 0 0 0 0 25 0 1 0 893412963 2633728 41 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65538 4 82432 0 0 0 17 0 0 0 0 /proc/11161/statm: 643 41 0 194 0 29 0 [startup+0.236222 s] /proc/loadavg: 0.90 0.94 0.90 5/39 11161 /proc/meminfo: memFree=37532/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 0.09 Current children cumulated vsize (KiB) 2572 [startup+0.306157 s] /proc/loadavg: 0.90 0.94 0.90 5/39 11161 /proc/meminfo: memFree=37532/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 0.09 Current children cumulated vsize (KiB) 2572 [startup+0.406176 s] /proc/loadavg: 0.90 0.94 0.90 5/39 11161 /proc/meminfo: memFree=37532/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 0.09 Current children cumulated vsize (KiB) 2572 [startup+0.706241 s] /proc/loadavg: 0.90 0.94 0.90 5/39 11161 /proc/meminfo: memFree=37532/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 Current children cumulated CPU time (s) 0.09 Current children cumulated vsize (KiB) 2572 [startup+1.50645 s] /proc/loadavg: 0.90 0.94 0.90 2/40 11163 /proc/meminfo: memFree=34300/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=5924 CPUtime=1.39 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 1194 0 0 0 138 1 0 0 25 0 1 0 893412974 6066176 1003 1283457024 134512640 135887319 4294914688 18446744073709551615 134615604 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 1481 1003 137 336 0 1143 0 Current children cumulated CPU time (s) 1.48 Current children cumulated vsize (KiB) 8496 [startup+3.1068 s] /proc/loadavg: 0.90 0.94 0.90 2/40 11163 /proc/meminfo: memFree=33308/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=6484 CPUtime=3 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 1351 0 0 0 297 3 0 0 25 0 1 0 893412974 6639616 1143 1283457024 134512640 135887319 4294914688 18446744073709551615 134603861 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 1621 1143 137 336 0 1283 0 Current children cumulated CPU time (s) 3.09 Current children cumulated vsize (KiB) 9056 [startup+6.30748 s] /proc/loadavg: 0.91 0.94 0.90 2/40 11163 /proc/meminfo: memFree=32440/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=7144 CPUtime=6.19 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 1558 0 0 0 612 7 0 0 25 0 1 0 893412974 7315456 1328 1283457024 134512640 135887319 4294914688 18446744073709551615 134614978 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 1786 1328 137 336 0 1448 0 Current children cumulated CPU time (s) 6.28 Current children cumulated vsize (KiB) 9716 [startup+12.7088 s] /proc/loadavg: 0.92 0.94 0.90 2/40 11163 /proc/meminfo: memFree=31696/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=8216 CPUtime=12.58 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 1852 0 0 0 1246 12 0 0 25 0 1 0 893412974 8413184 1573 1283457024 134512640 135887319 4294914688 18446744073709551615 134615064 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 2054 1573 137 336 0 1716 0 Current children cumulated CPU time (s) 12.67 Current children cumulated vsize (KiB) 10788 [startup+25.5115 s] /proc/loadavg: 0.93 0.95 0.90 2/40 11163 /proc/meminfo: memFree=30704/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=8780 CPUtime=25.37 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 2050 0 0 0 2516 21 0 0 25 0 1 0 893412974 8990720 1725 1283457024 134512640 135887319 4294914688 18446744073709551615 134525478 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 2195 1725 137 336 0 1857 0 Current children cumulated CPU time (s) 25.46 Current children cumulated vsize (KiB) 11352 [startup+51.1074 s] /proc/loadavg: 0.96 0.95 0.91 2/40 11163 /proc/meminfo: memFree=29464/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=10024 CPUtime=50.95 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 2431 0 0 0 5057 38 0 0 25 0 1 0 893412974 10264576 2031 1283457024 134512640 135887319 4294914688 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 2506 2031 137 336 0 2168 0 Current children cumulated CPU time (s) 51.04 Current children cumulated vsize (KiB) 12596 [startup+102.31 s] /proc/loadavg: 0.98 0.95 0.91 2/40 11163 /proc/meminfo: memFree=27852/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=11588 CPUtime=102.09 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 2936 0 0 0 10140 69 0 0 25 0 1 0 893412974 11866112 2407 1283457024 134512640 135887319 4294914688 18446744073709551615 134615061 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 2897 2407 137 336 0 2559 0 Current children cumulated CPU time (s) 102.18 Current children cumulated vsize (KiB) 14160 [startup+162.304 s] /proc/loadavg: 0.99 0.96 0.91 2/40 11163 /proc/meminfo: memFree=26488/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=12952 CPUtime=161.99 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 3343 0 0 0 16101 98 0 0 25 0 1 0 893412974 13262848 2728 1283457024 134512640 135887319 4294914688 18446744073709551615 134525040 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 3238 2728 137 336 0 2900 0 Current children cumulated CPU time (s) 162.08 Current children cumulated vsize (KiB) 15524 [startup+222.311 s] /proc/loadavg: 0.99 0.96 0.91 2/40 11163 /proc/meminfo: memFree=25248/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=14180 CPUtime=221.91 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 3700 0 0 0 22066 125 0 0 25 0 1 0 893412974 14520320 3022 1283457024 134512640 135887319 4294914688 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 3545 3022 137 336 0 3207 0 Current children cumulated CPU time (s) 222 Current children cumulated vsize (KiB) 16752 [startup+282.306 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11163 /proc/meminfo: memFree=24752/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=14864 CPUtime=281.8 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 3934 0 0 0 28030 150 0 0 25 0 1 0 893412974 15220736 3200 1283457024 134512640 135887319 4294914688 18446744073709551615 134615616 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 3716 3200 137 336 0 3378 0 Current children cumulated CPU time (s) 281.89 Current children cumulated vsize (KiB) 17436 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.508 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11163 /proc/meminfo: memFree=24132/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=15272 CPUtime=289.99 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 4030 0 0 0 28847 152 0 0 25 0 1 0 893412974 15638528 3289 1283457024 134512640 135887319 4294914688 18446744073709551615 134615108 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 3818 3289 137 336 0 3480 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 17844 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.508 s] /proc/loadavg: 0.99 0.97 0.91 2/40 11163 /proc/meminfo: memFree=24132/1048576 swapFree=2095372/2097144 [pid=11160] ppid=11159 vsize=2572 CPUtime=0.09 /proc/11160/stat : 11160 (cudf2pbo4parano) S 11159 11160 9023 34817 9081 4202496 403 535 0 0 1 0 6 2 24 0 1 0 893412963 2633728 282 1283457024 134512640 135304128 4288701488 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11160/statm: 643 282 241 194 0 29 0 [pid=11163] ppid=11160 vsize=15272 CPUtime=289.99 /proc/11163/stat : 11163 (bmo-pblex32) R 11160 11160 9023 34817 9081 4202496 4030 0 0 0 28847 152 0 0 25 0 1 0 893412974 15638528 3289 1283457024 134512640 135887319 4294914688 18446744073709551615 134615108 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11163/statm: 3818 3289 137 336 0 3480 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 17844 Child status: 0 Real time (s): 290.535 CPU time (s): 290.106 CPU user time (s): 288.554 CPU system time (s): 1.5521 CPU usage (%): 99.8524 Max. virtual memory (cumulated for all children) (KiB): 17844 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.554 system time used= 1.5521 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 6408 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= 10 involuntary context switches= 3675 runsolver used 0 second user time and 0 second system time The end