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/rand494.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./cudf2pbo4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand494.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012081719/cudf2pbo4trendy-1.0/rand494.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.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.99 0.96 0.91 4/39 10982 /proc/meminfo: memFree=82556/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=0 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893300168 2629632 278 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 278 238 194 0 28 0 [pid=10982] ppid=10981 vsize=2048 CPUtime=0.01 /proc/10982/stat : 10982 (cudf_msu32) R 10981 10981 9023 34817 9081 4202496 304 0 0 0 1 0 0 0 25 0 1 0 893300168 2097152 197 1283457024 134512640 136125367 4291759952 18446744073709551615 134717932 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10982/statm: 512 197 141 394 0 116 0 [startup+0.13551 s] /proc/loadavg: 0.99 0.96 0.91 4/39 10982 /proc/meminfo: memFree=82556/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=0 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893300168 2629632 278 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 278 238 194 0 28 0 [pid=10982] ppid=10981 vsize=7652 CPUtime=0.14 /proc/10982/stat : 10982 (cudf_msu32) R 10981 10981 9023 34817 9081 4202496 1721 0 0 0 14 0 0 0 25 0 1 0 893300168 7835648 1614 1283457024 134512640 136125367 4291759952 18446744073709551615 134717796 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10982/statm: 1913 1614 142 394 0 1517 0 Current children cumulated CPU time (s) 0.14 Current children cumulated vsize (KiB) 10220 [startup+0.20553 s] /proc/loadavg: 0.99 0.96 0.91 4/39 10982 /proc/meminfo: memFree=82556/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=0 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893300168 2629632 278 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 278 238 194 0 28 0 [pid=10982] ppid=10981 vsize=10424 CPUtime=0.21 /proc/10982/stat : 10982 (cudf_msu32) R 10981 10981 9023 34817 9081 4202496 2407 0 0 0 21 0 0 0 25 0 1 0 893300168 10674176 2300 1283457024 134512640 136125367 4291759952 18446744073709551615 134717743 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10982/statm: 2606 2300 142 394 0 2210 0 Current children cumulated CPU time (s) 0.21 Current children cumulated vsize (KiB) 12992 [startup+0.305551 s] /proc/loadavg: 0.99 0.96 0.91 4/39 10982 /proc/meminfo: memFree=82556/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=0 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893300168 2629632 278 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 278 238 194 0 28 0 [pid=10982] ppid=10981 vsize=13920 CPUtime=0.31 /proc/10982/stat : 10982 (cudf_msu32) R 10981 10981 9023 34817 9081 4202496 3288 0 0 0 31 0 0 0 25 0 1 0 893300168 14254080 3181 1283457024 134512640 136125367 4291759952 18446744073709551615 134717783 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10982/statm: 3480 3181 143 394 0 3084 0 Current children cumulated CPU time (s) 0.31 Current children cumulated vsize (KiB) 16488 [startup+0.705646 s] /proc/loadavg: 0.99 0.96 0.91 4/39 10982 /proc/meminfo: memFree=82556/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=0 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893300168 2629632 278 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 278 238 194 0 28 0 [pid=10982] ppid=10981 vsize=26128 CPUtime=0.7 /proc/10982/stat : 10982 (cudf_msu32) R 10981 10981 9023 34817 9081 4202496 6350 0 0 0 68 2 0 0 25 0 1 0 893300168 26755072 6243 1283457024 134512640 136125367 4291759952 18446744073709551615 134717814 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10982/statm: 6532 6243 143 394 0 6136 0 Current children cumulated CPU time (s) 0.7 Current children cumulated vsize (KiB) 28696 [startup+1.50587 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10983 /proc/meminfo: memFree=47940/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=0 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 381 0 0 0 0 0 0 0 18 0 1 0 893300168 2629632 278 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 278 238 194 0 28 0 [pid=10982] ppid=10981 vsize=52496 CPUtime=1.5 /proc/10982/stat : 10982 (cudf_msu32) R 10981 10981 9023 34817 9081 4202496 12995 0 0 0 141 9 0 0 25 0 1 0 893300168 53755904 12838 1283457024 134512640 136125367 4291759952 18446744073709551615 134610136 0 0 0 25121 0 0 0 17 0 0 0 0 /proc/10982/statm: 13124 12838 160 394 0 12728 0 Current children cumulated CPU time (s) 1.5 Current children cumulated vsize (KiB) 55064 [startup+3.1081 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10983 /proc/meminfo: memFree=21776/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 Current children cumulated CPU time (s) 2.41 Current children cumulated vsize (KiB) 2568 heavy processes: [startup+6.30908 s] /proc/loadavg: 0.99 0.96 0.91 2/40 10984 /proc/meminfo: memFree=50420/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=38568 CPUtime=3.83 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 10905 0 0 0 297 86 0 0 25 0 1 0 893300409 39493632 9066 1283457024 134512640 135887319 4291081904 18446744073709551615 135329116 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 9642 9066 144 336 0 9304 0 Current children cumulated CPU time (s) 6.24 Current children cumulated vsize (KiB) 41136 [startup+12.7109 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=30208/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=58372 CPUtime=10.21 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 19583 0 0 0 819 202 0 0 25 0 1 0 893300409 59772928 14124 1283457024 134512640 135887319 4291081904 18446744073709551615 134624789 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 14593 14124 144 336 0 14255 0 Current children cumulated CPU time (s) 12.62 Current children cumulated vsize (KiB) 60940 [startup+25.5053 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=12848/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=67396 CPUtime=22.88 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 22864 0 0 0 1983 305 0 0 25 0 1 0 893300409 69013504 16416 1283457024 134512640 135887319 4291081904 18446744073709551615 134526496 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 16849 16416 144 336 0 16511 0 Current children cumulated CPU time (s) 25.29 Current children cumulated vsize (KiB) 69964 [startup+51.1047 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=11112/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=69252 CPUtime=48.46 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 23336 0 0 0 4536 310 0 0 25 0 1 0 893300409 70914048 16866 1283457024 134512640 135887319 4291081904 18446744073709551615 134603626 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 17313 16866 144 336 0 16975 0 Current children cumulated CPU time (s) 50.87 Current children cumulated vsize (KiB) 71820 [startup+102.307 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=7268/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=72816 CPUtime=99.62 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 24255 0 0 0 9650 312 0 0 25 0 1 0 893300409 74563584 17780 1283457024 134512640 135887319 4291081904 18446744073709551615 134525305 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 18204 17780 144 336 0 17866 0 Current children cumulated CPU time (s) 102.03 Current children cumulated vsize (KiB) 75384 [startup+162.311 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=5736/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=75588 CPUtime=159.57 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 24938 0 0 0 15644 313 0 0 25 0 1 0 893300409 77402112 18446 1283457024 134512640 135887319 4291081904 18446744073709551615 134603584 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 18897 18446 144 336 0 18559 0 Current children cumulated CPU time (s) 161.98 Current children cumulated vsize (KiB) 78156 [startup+222.305 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=6040/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=81040 CPUtime=219.52 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 26337 0 0 0 21636 316 0 0 25 0 1 0 893300409 82984960 19811 1283457024 134512640 135887319 4291081904 18446744073709551615 134603666 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 20260 19811 144 336 0 19922 0 Current children cumulated CPU time (s) 221.93 Current children cumulated vsize (KiB) 83608 [startup+282.31 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=5228/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=87528 CPUtime=279.49 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 28022 0 0 0 27627 322 0 0 25 0 1 0 893300409 89628672 21446 1283457024 134512640 135887319 4291081904 18446744073709551615 134614962 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 21882 21446 144 336 0 21544 0 Current children cumulated CPU time (s) 281.9 Current children cumulated vsize (KiB) 90096 Maximum CPU time exceeded: sending signal-name then SIGKILL [startup+290.412 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=5376/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2568 CPUtime=2.41 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 400 14874 0 0 0 0 196 45 20 0 1 0 893300168 2629632 281 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 642 281 241 194 0 28 0 [pid=10984] ppid=10981 vsize=88452 CPUtime=287.59 /proc/10984/stat : 10984 (bmo-pblex32) R 10981 10981 9023 34817 9081 4202496 28248 0 0 0 28437 322 0 0 25 0 1 0 893300409 90574848 21667 1283457024 134512640 135887319 4291081904 18446744073709551615 134614964 0 0 0 16899 0 0 0 17 0 0 0 0 /proc/10984/statm: 22113 21667 144 336 0 21775 0 Current children cumulated CPU time (s) 290 Current children cumulated vsize (KiB) 91020 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.527 s] /proc/loadavg: 0.99 0.97 0.91 2/40 10984 /proc/meminfo: memFree=5376/1048576 swapFree=2095372/2097144 [pid=10981] ppid=10980 vsize=2576 CPUtime=290.04 /proc/10981/stat : 10981 (cudf2pbo4trendy) S 10980 10981 9023 34817 9081 4202496 442 43540 0 0 0 0 28634 370 20 0 1 0 893300168 2637824 287 1283457024 134512640 135304128 4289858784 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0 /proc/10981/statm: 644 287 245 194 0 30 0 Current children cumulated CPU time (s) 290.04 Current children cumulated vsize (KiB) 2576 Child status: 0 Real time (s): 290.537 CPU time (s): 290.126 CPU user time (s): 286.422 CPU system time (s): 3.70423 CPU usage (%): 99.8585 Max. virtual memory (cumulated for all children) (KiB): 91020 getrusage(RUSAGE_CHILDREN,...) data: user time used= 286.422 system time used= 3.70423 maximum resident set size= 0 integral shared memory size= 0 integral unshared data size= 0 integral unshared stack size= 0 page reclaims= 45775 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= 27 involuntary context switches= 8748 runsolver used 0 second user time and 0 second system time The end