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/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./cudf2msu4trendy-1.0 /home/misc2010/data/2010/debian-dudf//218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/cudf2msu4trendy-1.0/218091ce-4bcc-11df-bc4e-00163e7a6f5e.cudf.debian-dudf.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: 1.07 1.01 1.00 3/41 9827
/proc/meminfo: memFree=620860/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=1916 CPUtime=0
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 238 0 0 0 0 0 0 0 25 0 1 0 879005288 1961984 178 1283457024 134512640 136120023 4289651952 18446744073709551615 135545164 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 479 178 137 393 0 84 0

[startup+0.113797 s]
/proc/loadavg: 1.07 1.01 1.00 3/41 9827
/proc/meminfo: memFree=620860/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=6332 CPUtime=0.11
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 1330 0 0 0 11 0 0 0 25 0 1 0 879005288 6483968 1270 1283457024 134512640 136120023 4289651952 18446744073709551615 134712159 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 1583 1270 137 393 0 1188 0
Current children cumulated CPU time (s) 0.11
Current children cumulated vsize (KiB) 8904

[startup+0.213815 s]
/proc/loadavg: 1.07 1.01 1.00 3/41 9827
/proc/meminfo: memFree=620860/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=9764 CPUtime=0.21
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 2213 0 0 0 20 1 0 0 25 0 1 0 879005288 9998336 2153 1283457024 134512640 136120023 4289651952 18446744073709551615 134711844 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 2441 2153 137 393 0 2046 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12336

[startup+0.31383 s]
/proc/loadavg: 1.07 1.01 1.00 3/41 9827
/proc/meminfo: memFree=620860/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=12864 CPUtime=0.31
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 2987 0 0 0 30 1 0 0 25 0 1 0 879005288 13172736 2927 1283457024 134512640 136120023 4289651952 18446744073709551615 134712061 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 3216 2927 138 393 0 2821 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 15436

[startup+0.713932 s]
/proc/loadavg: 1.07 1.01 1.00 3/41 9827
/proc/meminfo: memFree=620860/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=23620 CPUtime=0.71
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 5677 0 0 0 68 3 0 0 25 0 1 0 879005288 24186880 5617 1283457024 134512640 136120023 4289651952 18446744073709551615 134712142 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 5905 5617 138 393 0 5510 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 26192

[startup+1.51424 s]
/proc/loadavg: 1.07 1.01 1.00 2/42 9828
/proc/meminfo: memFree=589248/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=50892 CPUtime=1.51
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 12875 0 0 0 144 7 0 0 25 0 1 0 879005288 52113408 12422 1283457024 134512640 136120023 4289651952 18446744073709551615 135524234 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 12723 12422 149 393 0 12328 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 53464

[startup+3.11483 s]
/proc/loadavg: 1.06 1.01 1.00 2/42 9828
/proc/meminfo: memFree=509640/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=112860 CPUtime=3.11
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 28412 0 0 0 297 14 0 0 25 0 1 0 879005288 115568640 27929 1283457024 134512640 136120023 4289651952 18446744073709551615 134870003 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 28215 27929 178 393 0 27820 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 115432

[startup+6.31584 s]
/proc/loadavg: 1.06 1.01 1.00 2/42 9828
/proc/meminfo: memFree=509152/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=113128 CPUtime=6.31
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 28531 0 0 0 617 14 0 0 25 0 1 0 879005288 115843072 28035 1283457024 134512640 136120023 4289651952 18446744073709551615 134837910 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 28282 28035 182 393 0 27887 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 115700

[startup+12.7081 s]
/proc/loadavg: 1.05 1.01 1.00 2/42 9828
/proc/meminfo: memFree=509028/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=113128 CPUtime=12.69
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 28531 0 0 0 1255 14 0 0 25 0 1 0 879005288 115843072 28035 1283457024 134512640 136120023 4289651952 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 28282 28035 182 393 0 27887 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 115700

[startup+25.5115 s]
/proc/loadavg: 1.04 1.01 1.00 2/42 9828
/proc/meminfo: memFree=509028/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=113128 CPUtime=25.49
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 28531 0 0 0 2534 15 0 0 25 0 1 0 879005288 115843072 28035 1283457024 134512640 136120023 4289651952 18446744073709551615 134869791 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 28282 28035 182 393 0 27887 0
Current children cumulated CPU time (s) 25.49
Current children cumulated vsize (KiB) 115700

[startup+51.1078 s]
/proc/loadavg: 1.03 1.01 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=51.06
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 5090 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 134872419 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 51.06
Current children cumulated vsize (KiB) 121116

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

[startup+51.2079 s]
/proc/loadavg: 1.03 1.01 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=51.16
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 5100 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 135511683 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 51.16
Current children cumulated vsize (KiB) 121116

[startup+64.0114 s]
/proc/loadavg: 1.02 1.00 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=63.95
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 6379 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 135521152 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 63.95
Current children cumulated vsize (KiB) 121116

[startup+70.4037 s]
/proc/loadavg: 1.02 1.00 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=70.33
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 7017 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 134869928 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 70.33
Current children cumulated vsize (KiB) 121116

[startup+73.6044 s]
/proc/loadavg: 1.02 1.00 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=73.53
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 7337 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 134870892 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 73.53
Current children cumulated vsize (KiB) 121116

[startup+75.2048 s]
/proc/loadavg: 1.02 1.00 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=75.13
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 7497 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 135524112 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 75.13
Current children cumulated vsize (KiB) 121116

[startup+76.005 s]
/proc/loadavg: 1.02 1.00 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=75.93
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29894 0 0 0 7577 16 0 0 25 0 1 0 879005288 121389056 29393 1283457024 134512640 136120023 4289651952 18446744073709551615 134870168 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29393 182 393 0 29241 0
Current children cumulated CPU time (s) 75.93
Current children cumulated vsize (KiB) 121116

[startup+76.2051 s]
/proc/loadavg: 1.02 1.00 1.00 2/42 9828
/proc/meminfo: memFree=503572/1048576 swapFree=2080288/2097144
[pid=9826] ppid=9825 vsize=2572 CPUtime=0
/proc/9826/stat : 9826 (cudf2msu4trendy) S 9825 9826 4159 34819 4229 4202496 375 0 0 0 0 0 0 0 25 0 1 0 879005288 2633728 271 1283457024 134512640 135304128 4287363760 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/9826/statm: 643 271 231 194 0 29 0
[pid=9827] ppid=9826 vsize=118544 CPUtime=76.14
/proc/9827/stat : 9827 (cudf_msu32) R 9826 9826 4159 34819 4229 4202496 29908 0 0 0 7596 18 0 0 25 0 1 0 879005288 121389056 29407 1283457024 134512640 136120023 4289651952 18446744073709551615 135589886 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/9827/statm: 29636 29407 196 393 0 29241 0
Current children cumulated CPU time (s) 76.14
Current children cumulated vsize (KiB) 121116

Child status: 0
Real time (s): 76.2906
CPU time (s): 76.2168
CPU user time (s): 76.0208
CPU system time (s): 0.196012
CPU usage (%): 99.9032
Max. virtual memory (cumulated for all children) (KiB): 121116

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 76.0208
system time used= 0.196012
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 30296
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= 3
involuntary context switches= 958

runsolver used 0 second user time and 0 second system time

The end