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/rand753.sarge.cudf.sarge.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge/rand753.sarge.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand753.sarge.cudf.sarge.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.94 0.95 0.91 4/35 11966 /proc/meminfo: memFree=41260/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 19 0 1 0 893824251 2633728 278 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 278 238 194 0 29 0 [pid=11966] ppid=11965 vsize=2052 CPUtime=0.01 /proc/11966/stat : 11966 (cudf_msu32) R 11965 11965 9023 34817 9081 4202496 310 0 0 0 1 0 0 0 25 0 1 0 893824251 2101248 203 1283457024 134512640 136125367 4287816640 18446744073709551615 134728351 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11966/statm: 513 203 141 394 0 117 0 [startup+0.13564 s] /proc/loadavg: 0.94 0.95 0.91 4/35 11966 /proc/meminfo: memFree=41260/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 19 0 1 0 893824251 2633728 278 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 278 238 194 0 29 0 [pid=11966] ppid=11965 vsize=7368 CPUtime=0.14 /proc/11966/stat : 11966 (cudf_msu32) R 11965 11965 9023 34817 9081 4202496 1655 0 0 0 14 0 0 0 25 0 1 0 893824251 7544832 1548 1283457024 134512640 136125367 4287816640 18446744073709551615 134727103 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11966/statm: 1842 1548 142 394 0 1446 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 9940 [startup+0.205652 s] /proc/loadavg: 0.94 0.95 0.91 4/35 11966 /proc/meminfo: memFree=41260/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 19 0 1 0 893824251 2633728 278 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 278 238 194 0 29 0 [pid=11966] ppid=11965 vsize=9692 CPUtime=0.2 /proc/11966/stat : 11966 (cudf_msu32) R 11965 11965 9023 34817 9081 4202496 2238 0 0 0 20 0 0 0 25 0 1 0 893824251 9924608 2131 1283457024 134512640 136125367 4287816640 18446744073709551615 135176216 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11966/statm: 2423 2131 152 394 0 2027 0 Current children cumulated CPU time (s) 0.2 Current children cumulated vsize (KiB) 12264 [startup+0.305657 s] /proc/loadavg: 0.94 0.95 0.91 4/35 11966 /proc/meminfo: memFree=41260/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 19 0 1 0 893824251 2633728 278 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 278 238 194 0 29 0 [pid=11966] ppid=11965 vsize=12296 CPUtime=0.3 /proc/11966/stat : 11966 (cudf_msu32) R 11965 11965 9023 34817 9081 4202496 2900 0 0 0 29 1 0 0 25 0 1 0 893824251 12591104 2793 1283457024 134512640 136125367 4287816640 18446744073709551615 135526573 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/11966/statm: 3074 2793 164 394 0 2678 0 Current children cumulated CPU time (s) 0.3 Current children cumulated vsize (KiB) 14868 [startup+0.705712 s] /proc/loadavg: 0.94 0.95 0.91 4/35 11966 /proc/meminfo: memFree=41260/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 Current children cumulated CPU time (s) 0.35 Current children cumulated vsize (KiB) 2572 [startup+1.50582 s] /proc/loadavg: 0.95 0.95 0.91 2/36 11968 /proc/meminfo: memFree=34792/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=8132 CPUtime=1.16 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 2432 0 0 0 114 2 0 0 25 0 1 0 893824286 8327168 1669 1283457024 134512640 135887319 4288031728 18446744073709551615 134526506 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 2033 1669 144 336 0 1695 0 Current children cumulated CPU time (s) 1.51 Current children cumulated vsize (KiB) 10704 [startup+3.10611 s] /proc/loadavg: 0.95 0.95 0.91 2/36 11968 /proc/meminfo: memFree=34792/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=8528 CPUtime=2.76 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 2520 0 0 0 274 2 0 0 25 0 1 0 893824286 8732672 1752 1283457024 134512640 135887319 4288031728 18446744073709551615 134624367 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 2132 1752 144 336 0 1794 0 Current children cumulated CPU time (s) 3.11 Current children cumulated vsize (KiB) 11100 [startup+6.30672 s] /proc/loadavg: 0.95 0.95 0.91 2/36 11968 /proc/meminfo: memFree=33808/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=9324 CPUtime=5.94 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 2769 0 0 0 592 2 0 0 25 0 1 0 893824286 9547776 1978 1283457024 134512640 135887319 4288031728 18446744073709551615 134603607 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 2331 1978 144 336 0 1993 0 Current children cumulated CPU time (s) 6.29 Current children cumulated vsize (KiB) 11896 [startup+12.7081 s] /proc/loadavg: 0.96 0.95 0.91 2/36 11968 /proc/meminfo: memFree=32444/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=10512 CPUtime=12.34 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 3087 0 0 0 1225 9 0 0 25 0 1 0 893824286 10764288 2250 1283457024 134512640 135887319 4288031728 18446744073709551615 134526961 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 2628 2250 144 336 0 2290 0 Current children cumulated CPU time (s) 12.69 Current children cumulated vsize (KiB) 13084 [startup+25.5105 s] /proc/loadavg: 0.96 0.95 0.91 2/36 11968 /proc/meminfo: memFree=32196/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=10824 CPUtime=25.14 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 3207 0 0 0 2500 14 0 0 25 0 1 0 893824286 11083776 2340 1283457024 134512640 135887319 4288031728 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 2706 2340 144 336 0 2368 0 Current children cumulated CPU time (s) 25.49 Current children cumulated vsize (KiB) 13396 [startup+51.1062 s] /proc/loadavg: 0.97 0.95 0.91 2/36 11968 /proc/meminfo: memFree=31204/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=11788 CPUtime=50.7 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 3474 0 0 0 5040 30 0 0 25 0 1 0 893824286 12070912 2582 1283457024 134512640 135887319 4288031728 18446744073709551615 134615057 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 2947 2582 144 336 0 2609 0 Current children cumulated CPU time (s) 51.05 Current children cumulated vsize (KiB) 14360 [startup+102.307 s] /proc/loadavg: 0.99 0.96 0.91 2/36 11968 /proc/meminfo: memFree=30336/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=12652 CPUtime=101.87 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 3761 0 0 0 10117 70 0 0 25 0 1 0 893824286 12955648 2784 1283457024 134512640 135887319 4288031728 18446744073709551615 134603576 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 3163 2784 144 336 0 2825 0 Current children cumulated CPU time (s) 102.22 Current children cumulated vsize (KiB) 15224 [startup+162.309 s] /proc/loadavg: 0.99 0.96 0.91 2/36 11968 /proc/meminfo: memFree=29716/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=13264 CPUtime=161.85 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 3943 0 0 0 16075 110 0 0 25 0 1 0 893824286 13582336 2930 1283457024 134512640 135887319 4288031728 18446744073709551615 134617651 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 3316 2930 144 336 0 2978 0 Current children cumulated CPU time (s) 162.2 Current children cumulated vsize (KiB) 15836 [startup+222.312 s] /proc/loadavg: 0.99 0.97 0.91 2/36 11968 /proc/meminfo: memFree=29096/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=13800 CPUtime=221.81 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 4105 0 0 0 22035 146 0 0 25 0 1 0 893824286 14131200 3066 1283457024 134512640 135887319 4288031728 18446744073709551615 134526950 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 3450 3066 144 336 0 3112 0 Current children cumulated CPU time (s) 222.16 Current children cumulated vsize (KiB) 16372 [startup+282.307 s] /proc/loadavg: 0.99 0.97 0.91 2/36 11968 /proc/meminfo: memFree=28600/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=14588 CPUtime=281.73 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 4347 0 0 0 27991 182 0 0 25 0 1 0 893824286 14938112 3239 1283457024 134512640 135887319 4288031728 18446744073709551615 134624319 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 3647 3239 144 336 0 3309 0 Current children cumulated CPU time (s) 282.08 Current children cumulated vsize (KiB) 17160 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.308 s] /proc/loadavg: 0.99 0.97 0.91 2/36 11968 /proc/meminfo: memFree=28352/1048576 swapFree=2095372/2097144 [pid=11965] ppid=11964 vsize=2572 CPUtime=0.35 /proc/11965/stat : 11965 (cudf2pbo4trendy) S 11964 11965 9023 34817 9081 4202496 401 2902 0 0 0 0 32 3 23 0 1 0 893824251 2633728 281 1283457024 134512640 135304128 4287769408 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/11965/statm: 643 281 241 194 0 29 0 [pid=11968] ppid=11965 vsize=14588 CPUtime=289.73 /proc/11968/stat : 11968 (bmo-pblex32) R 11965 11965 9023 34817 9081 4202496 4353 0 0 0 28785 188 0 0 25 0 1 0 893824286 14938112 3245 1283457024 134512640 135887319 4288031728 18446744073709551615 134525472 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/11968/statm: 3647 3245 144 336 0 3309 0 Current children cumulated CPU time (s) 290.08 Current children cumulated vsize (KiB) 17160 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.342 CPU time (s): 290.122 CPU user time (s): 288.206 CPU system time (s): 1.91612 CPU usage (%): 99.9243 Max. virtual memory (cumulated for all children) (KiB): 17160 getrusage(RUSAGE_CHILDREN,...) data: user time used= 288.206 system time used= 1.91612 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 9160 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= 3718 runsolver used 0 second user time and 0 second system time The end