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/201012091704/cudf2pbo4user-1.0/rand4d6b1c.cudf.difficult.log.runsolver ./cudf2pbo4user-1.0 /home/misc2010/data/2010/difficult//rand4d6b1c.cudf /home/misc2010/tmp/201012091704/cudf2pbo4user-1.0/rand4d6b1c.cudf.difficult.result -changed,-notuptodate,-removed,-new 

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.87 0.97 0.99 3/39 5775
/proc/meminfo: memFree=377996/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=0
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 383 0 0 0 0 0 0 0 18 0 1 0 901314664 2629632 279 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 279 240 194 0 28 0
[pid=5775] ppid=5774 vsize=2568 CPUtime=0
/proc/5775/stat : 5775 (cudf2pbo4user-1) D 5774 5774 25521 34816 2180 4202560 79 0 0 0 0 0 0 0 18 0 1 0 901314664 2629632 102 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 0 0 0 18446744071564252162 0 0 17 0 0 0 0
/proc/5775/statm: 642 102 62 194 0 28 0

[startup+0.161183 s]
/proc/loadavg: 0.87 0.97 0.99 3/39 5775
/proc/meminfo: memFree=377996/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=0
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 383 0 0 0 0 0 0 0 18 0 1 0 901314664 2629632 279 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 279 240 194 0 28 0
[pid=5775] ppid=5774 vsize=8252 CPUtime=0.14
/proc/5775/stat : 5775 (cudf_msu32) R 5774 5774 25521 34816 2180 4202496 1891 0 0 0 13 1 0 0 25 0 1 0 901314664 8450048 1784 1283457024 134512640 136125367 4288560208 18446744073709551615 134717871 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/5775/statm: 2063 1784 146 394 0 1667 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10820

[startup+0.20755 s]
/proc/loadavg: 0.87 0.97 0.99 3/39 5775
/proc/meminfo: memFree=377996/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=0
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 383 0 0 0 0 0 0 0 18 0 1 0 901314664 2629632 279 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 279 240 194 0 28 0
[pid=5775] ppid=5774 vsize=10112 CPUtime=0.19
/proc/5775/stat : 5775 (cudf_msu32) R 5774 5774 25521 34816 2180 4202496 2335 0 0 0 18 1 0 0 25 0 1 0 901314664 10354688 2228 1283457024 134512640 136125367 4288560208 18446744073709551615 134727088 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/5775/statm: 2528 2228 146 394 0 2132 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12680

[startup+0.307559 s]
/proc/loadavg: 0.87 0.97 0.99 3/39 5775
/proc/meminfo: memFree=377996/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=0
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 383 0 0 0 0 0 0 0 18 0 1 0 901314664 2629632 279 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 279 240 194 0 28 0
[pid=5775] ppid=5774 vsize=13740 CPUtime=0.28
/proc/5775/stat : 5775 (cudf_msu32) R 5774 5774 25521 34816 2180 4202496 3259 0 0 0 26 2 0 0 25 0 1 0 901314664 14069760 3152 1283457024 134512640 136125367 4288560208 18446744073709551615 135479520 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/5775/statm: 3435 3152 147 394 0 3039 0
Current children cumulated CPU time (s) 0.28
Current children cumulated vsize (KiB) 16308

[startup+0.707612 s]
/proc/loadavg: 0.87 0.97 0.99 3/39 5775
/proc/meminfo: memFree=377996/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=0
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 383 0 0 0 0 0 0 0 18 0 1 0 901314664 2629632 279 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 279 240 194 0 28 0
[pid=5775] ppid=5774 vsize=26212 CPUtime=0.69
/proc/5775/stat : 5775 (cudf_msu32) R 5774 5774 25521 34816 2180 4202496 6362 0 0 0 63 6 0 0 25 0 1 0 901314664 26841088 6255 1283457024 134512640 136125367 4288560208 18446744073709551615 134738362 0 0 0 25121 0 0 0 17 0 0 0 0
/proc/5775/statm: 6553 6255 147 394 0 6157 0
Current children cumulated CPU time (s) 0.69
Current children cumulated vsize (KiB) 28780

[startup+1.50876 s]
/proc/loadavg: 0.87 0.97 0.99 2/40 5777
/proc/meminfo: memFree=369296/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=9840 CPUtime=0.44
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 2660 0 0 0 27 17 0 0 22 0 1 0 901314769 10076160 2174 1283457024 134512640 135887319 4293790064 18446744073709551615 134600309 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 2460 2174 138 336 0 2122 0
Current children cumulated CPU time (s) 1.45
Current children cumulated vsize (KiB) 12408

[startup+3.10897 s]
/proc/loadavg: 0.88 0.97 0.99 2/40 5777
/proc/meminfo: memFree=368180/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=11156 CPUtime=2.02
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 3057 0 0 0 141 61 0 0 25 0 1 0 901314769 11423744 2515 1283457024 134512640 135887319 4293790064 18446744073709551615 134600658 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 2789 2515 138 336 0 2451 0
Current children cumulated CPU time (s) 3.03
Current children cumulated vsize (KiB) 13724

[startup+6.30955 s]
/proc/loadavg: 0.88 0.97 0.99 2/40 5777
/proc/meminfo: memFree=365824/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=13128 CPUtime=5.23
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 3576 0 0 0 438 85 0 0 25 0 1 0 901314769 13443072 2998 1283457024 134512640 135887319 4293790064 18446744073709551615 134615504 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 3282 2998 138 336 0 2944 0
Current children cumulated CPU time (s) 6.24
Current children cumulated vsize (KiB) 15696

[startup+12.7109 s]
/proc/loadavg: 0.90 0.97 0.99 2/40 5777
/proc/meminfo: memFree=362352/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=15632 CPUtime=11.62
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 4671 0 0 0 1069 93 0 0 25 0 1 0 901314769 16007168 3632 1283457024 134512640 135887319 4293790064 18446744073709551615 134605810 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 3908 3632 144 336 0 3570 0
Current children cumulated CPU time (s) 12.63
Current children cumulated vsize (KiB) 18200

[startup+25.5135 s]
/proc/loadavg: 0.91 0.97 0.99 2/40 5777
/proc/meminfo: memFree=360120/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=17752 CPUtime=24.41
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 5719 0 0 0 2345 96 0 0 25 0 1 0 901314769 18178048 4157 1283457024 134512640 135887319 4293790064 18446744073709551615 134527040 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 4438 4157 144 336 0 4100 0
Current children cumulated CPU time (s) 25.42
Current children cumulated vsize (KiB) 20320

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

[startup+25.6035 s]
/proc/loadavg: 0.91 0.97 0.99 2/40 5777
/proc/meminfo: memFree=360120/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=17752 CPUtime=24.5
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 5719 0 0 0 2354 96 0 0 25 0 1 0 901314769 18178048 4157 1283457024 134512640 135887319 4293790064 18446744073709551615 134605851 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 4438 4157 144 336 0 4100 0
Current children cumulated CPU time (s) 25.51
Current children cumulated vsize (KiB) 20320

[startup+32.005 s]
/proc/loadavg: 0.93 0.97 0.99 2/40 5777
/proc/meminfo: memFree=360120/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=17752 CPUtime=30.89
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 5721 0 0 0 2989 100 0 0 25 0 1 0 901314769 18178048 4159 1283457024 134512640 135887319 4293790064 18446744073709551615 134605916 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 4438 4159 144 336 0 4100 0
Current children cumulated CPU time (s) 31.9
Current children cumulated vsize (KiB) 20320

[startup+35.2057 s]
/proc/loadavg: 0.93 0.97 0.99 2/40 5777
/proc/meminfo: memFree=360120/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=18016 CPUtime=34.09
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 5785 0 0 0 3305 104 0 0 25 0 1 0 901314769 18448384 4214 1283457024 134512640 135887319 4293790064 18446744073709551615 134605808 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 4504 4214 144 336 0 4166 0
Current children cumulated CPU time (s) 35.1
Current children cumulated vsize (KiB) 20584

[startup+38.4063 s]
/proc/loadavg: 0.93 0.97 0.99 2/40 5777
/proc/meminfo: memFree=357516/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=20888 CPUtime=37.27
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 6880 0 0 0 3606 121 0 0 25 0 1 0 901314769 21389312 4956 1283457024 134512640 135887319 4293790064 18446744073709551615 134605808 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 5222 4956 144 336 0 4884 0
Current children cumulated CPU time (s) 38.28
Current children cumulated vsize (KiB) 23456

[startup+40.0066 s]
/proc/loadavg: 0.93 0.97 0.99 2/40 5777
/proc/meminfo: memFree=356772/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=21944 CPUtime=38.85
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 7133 0 0 0 3757 128 0 0 25 0 1 0 901314769 22470656 5208 1283457024 134512640 135887319 4293790064 18446744073709551615 134615180 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 5486 5208 144 336 0 5148 0
Current children cumulated CPU time (s) 39.86
Current children cumulated vsize (KiB) 24512

[startup+40.4067 s]
/proc/loadavg: 0.93 0.97 0.99 2/40 5777
/proc/meminfo: memFree=356772/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=21944 CPUtime=39.25
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 7137 0 0 0 3797 128 0 0 25 0 1 0 901314769 22470656 5212 1283457024 134512640 135887319 4293790064 18446744073709551615 134527024 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 5486 5212 144 336 0 5148 0
Current children cumulated CPU time (s) 40.26
Current children cumulated vsize (KiB) 24512

[startup+40.8068 s]
/proc/loadavg: 0.93 0.97 0.99 2/40 5777
/proc/meminfo: memFree=356524/1048576 swapFree=2095372/2097144
[pid=5774] ppid=5773 vsize=2568 CPUtime=1.01
/proc/5774/stat : 5774 (cudf2pbo4user-1) S 5773 5774 25521 34816 2180 4202496 400 7719 0 0 0 0 86 15 20 0 1 0 901314664 2629632 280 1283457024 134512640 135304128 4291251808 18446744073709551615 4294960130 0 65536 4 82434 18446744071564329979 0 0 17 0 0 0 0
/proc/5774/statm: 642 280 241 194 0 28 0
[pid=5777] ppid=5774 vsize=21944 CPUtime=39.65
/proc/5777/stat : 5777 (bmo-pblex32) R 5774 5774 25521 34816 2180 4202496 7141 0 0 0 3836 129 0 0 25 0 1 0 901314769 22470656 5216 1283457024 134512640 135887319 4293790064 18446744073709551615 134605930 0 0 0 16899 0 0 0 17 0 0 0 0
/proc/5777/statm: 5486 5216 144 336 0 5148 0
Current children cumulated CPU time (s) 40.66
Current children cumulated vsize (KiB) 24512

Child status: 0
Real time (s): 40.8726
CPU time (s): 40.7385
CPU user time (s): 39.2825
CPU system time (s): 1.45609
CPU usage (%): 99.672
Max. virtual memory (cumulated for all children) (KiB): 34032

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 39.2825
system time used= 1.45609
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 16877
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= 7235

runsolver used 0 second user time and 0 second system time

The end