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/cudf2msu4trendy-1.0/rand165.sarge-etch-lenny-squeeze-sid.cudf.sarge-etch-lenny-squeeze-sid.log.runsolver ./cudf2msu4trendy-1.0 /home/misc2010/data/icse/sarge-etch-lenny-squeeze-sid/rand165.sarge-etch-lenny-squeeze-sid.cudf /home/misc2010/tmp/201012070034/cudf2msu4trendy-1.0/rand165.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.85 0.97 0.99 2/40 8281
/proc/meminfo: memFree=876580/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=3024 CPUtime=0
/proc/8281/stat : 8281 (runsolver) D 8280 8281 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 21 0 1 0 878560586 3096576 94 1283457024 134512640 134586868 4290901232 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/8281/statm: 756 94 62 19 0 54 0

[startup+0.174957 s]
/proc/loadavg: 0.85 0.97 0.99 2/40 8281
/proc/meminfo: memFree=876580/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2576

[startup+0.206916 s]
/proc/loadavg: 0.85 0.97 0.99 2/40 8281
/proc/meminfo: memFree=876580/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2576

[startup+0.311182 s]
/proc/loadavg: 0.85 0.97 0.99 2/40 8281
/proc/meminfo: memFree=876580/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2576

[startup+0.711282 s]
/proc/loadavg: 0.85 0.97 0.99 2/40 8281
/proc/meminfo: memFree=876580/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
Current children cumulated CPU time (s) 0
Current children cumulated vsize (KiB) 2576

[startup+1.51153 s]
/proc/loadavg: 0.85 0.97 0.99 2/42 8283
/proc/meminfo: memFree=845304/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=45344 CPUtime=1.31
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 11144 0 17 0 125 6 0 0 25 0 1 0 878560587 46432256 11052 1283457024 134512640 136120023 4292943488 18446744073709551615 134615091 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 11336 11052 149 393 0 10941 0
Current children cumulated CPU time (s) 1.31
Current children cumulated vsize (KiB) 47920

[startup+3.11201 s]
/proc/loadavg: 0.85 0.97 0.99 2/42 8283
/proc/meminfo: memFree=769912/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=108208 CPUtime=2.92
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 38061 0 17 0 278 14 0 0 25 0 1 0 878560587 110804992 26734 1283457024 134512640 136120023 4292943488 18446744073709551615 134831620 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27052 26734 176 393 0 26657 0
Current children cumulated CPU time (s) 2.92
Current children cumulated vsize (KiB) 110784

[startup+6.31283 s]
/proc/loadavg: 0.86 0.97 0.99 2/42 8283
/proc/meminfo: memFree=768424/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=108208 CPUtime=6.11
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 38063 0 17 0 597 14 0 0 25 0 1 0 878560587 110804992 26736 1283457024 134512640 136120023 4292943488 18446744073709551615 134831717 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27052 26736 178 393 0 26657 0
Current children cumulated CPU time (s) 6.11
Current children cumulated vsize (KiB) 110784

[startup+12.7046 s]
/proc/loadavg: 0.87 0.97 0.99 2/42 8283
/proc/meminfo: memFree=768060/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=108404 CPUtime=12.49
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 38173 0 17 0 1235 14 0 0 25 0 1 0 878560587 111005696 26824 1283457024 134512640 136120023 4292943488 18446744073709551615 134840388 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27101 26824 182 393 0 26706 0
Current children cumulated CPU time (s) 12.49
Current children cumulated vsize (KiB) 110980

[startup+25.5079 s]
/proc/loadavg: 0.90 0.97 0.99 2/42 8283
/proc/meminfo: memFree=764464/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=111860 CPUtime=25.29
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 39074 0 17 0 2514 15 0 0 25 0 1 0 878560587 114544640 27709 1283457024 134512640 136120023 4292943488 18446744073709551615 134869805 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27965 27709 182 393 0 27570 0
Current children cumulated CPU time (s) 25.29
Current children cumulated vsize (KiB) 114436

[startup+51.1152 s]
/proc/loadavg: 0.93 0.97 0.99 2/42 8283
/proc/meminfo: memFree=764464/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=111860 CPUtime=50.87
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 39074 0 17 0 5068 19 0 0 25 0 1 0 878560587 114544640 27709 1283457024 134512640 136120023 4292943488 18446744073709551615 134831637 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27965 27709 182 393 0 27570 0
Current children cumulated CPU time (s) 50.87
Current children cumulated vsize (KiB) 114436

[startup+102.31 s]
/proc/loadavg: 0.97 0.97 0.99 2/42 8283
/proc/meminfo: memFree=766076/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=109544 CPUtime=102.02
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 39074 0 17 0 10183 19 0 0 25 0 1 0 878560587 112173056 27130 1283457024 134512640 136120023 4292943488 18446744073709551615 134849726 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27386 27130 182 393 0 26991 0
Current children cumulated CPU time (s) 102.02
Current children cumulated vsize (KiB) 112120

[startup+162.306 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=742516/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=135164 CPUtime=161.89
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 45445 0 17 0 16167 22 0 0 25 0 1 0 878560587 138407936 33245 1283457024 134512640 136120023 4292943488 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 33791 33245 182 393 0 33396 0
Current children cumulated CPU time (s) 161.89
Current children cumulated vsize (KiB) 137740

Solver just ended. Dumping a history of the last processes samples

[startup+179.211 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=733960/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=143480 CPUtime=178.79
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 47567 0 17 0 17855 24 0 0 25 0 1 0 878560587 146923520 35367 1283457024 134512640 136120023 4292943488 18446744073709551615 134869966 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 35870 35367 182 393 0 35475 0
Current children cumulated CPU time (s) 178.79
Current children cumulated vsize (KiB) 146056

[startup+192.005 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=726520/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=151004 CPUtime=191.56
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 49513 0 17 0 19126 30 0 0 25 0 1 0 878560587 154628096 37313 1283457024 134512640 136120023 4292943488 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 37751 37313 182 393 0 37356 0
Current children cumulated CPU time (s) 191.56
Current children cumulated vsize (KiB) 153580

[startup+195.206 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=723420/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=153776 CPUtime=194.77
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 50206 0 17 0 19446 31 0 0 25 0 1 0 878560587 157466624 38006 1283457024 134512640 136120023 4292943488 18446744073709551615 134869928 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 38444 38006 182 393 0 38049 0
Current children cumulated CPU time (s) 194.77
Current children cumulated vsize (KiB) 156352

[startup+196.807 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=722676/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=154700 CPUtime=196.37
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 50452 0 17 0 19606 31 0 0 25 0 1 0 878560587 158412800 38252 1283457024 134512640 136120023 4292943488 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 38675 38252 182 393 0 38280 0
Current children cumulated CPU time (s) 196.37
Current children cumulated vsize (KiB) 157276

[startup+197.607 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=722056/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=109624 CPUtime=197.17
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 50678 0 17 0 19685 32 0 0 25 0 1 0 878560587 112254976 27162 1283457024 134512640 136120023 4292943488 18446744073709551615 134887231 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27406 27162 182 393 0 27011 0
Current children cumulated CPU time (s) 197.17
Current children cumulated vsize (KiB) 112200

[startup+198.007 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=765952/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=109624 CPUtime=197.57
/proc/8283/stat : 8283 (cudf_msu32) R 8281 8281 4159 34819 4229 4202496 50678 0 17 0 19725 32 0 0 25 0 1 0 878560587 112254976 27162 1283457024 134512640 136120023 4292943488 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/8283/statm: 27406 27162 182 393 0 27011 0
Current children cumulated CPU time (s) 197.57
Current children cumulated vsize (KiB) 112200

[startup+198.203 s]
/proc/loadavg: 0.99 0.97 0.99 2/42 8283
/proc/meminfo: memFree=765952/1048576 swapFree=2080288/2097144
[pid=8281] ppid=8280 vsize=2576 CPUtime=0
/proc/8281/stat : 8281 (cudf2msu4trendy) S 8280 8281 4159 34819 4229 4202496 376 0 0 0 0 0 0 0 23 0 1 0 878560586 2637824 272 1283457024 134512640 135304128 4291749552 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/8281/statm: 644 272 231 194 0 30 0
[pid=8283] ppid=8281 vsize=109624 CPUtime=197.75
/proc/8283/stat : 8283 (cudf_msu32) D 8281 8281 4159 34819 4229 4202496 50680 0 17 0 19743 32 0 0 25 0 1 0 878560587 112254976 27164 1283457024 134512640 136120023 4292943488 18446744073709551615 135431040 0 0 0 16929 18446744071564332000 0 0 17 0 0 0 0
/proc/8283/statm: 27406 27164 184 393 0 27011 0
Current children cumulated CPU time (s) 197.75
Current children cumulated vsize (KiB) 112200

Child status: 0
Real time (s): 198.292
CPU time (s): 197.828
CPU user time (s): 197.492
CPU system time (s): 0.336021
CPU usage (%): 99.7659
Max. virtual memory (cumulated for all children) (KiB): 157640

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 197.492
system time used= 0.336021
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 51080
page faults= 18
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 24
involuntary context switches= 2384

runsolver used 0 second user time and 0 second system time

The end