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/201012091434/cudf2msu4user-1.0/randa870aa.cudf.difficult.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/difficult//randa870aa.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/randa870aa.cudf.difficult.result -changed,-removed,-unmet_recommends,-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: 1.32 1.14 1.06 5/39 431
/proc/meminfo: memFree=371040/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=2444 CPUtime=0.01
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 383 0 0 0 1 0 0 0 25 0 1 0 900571909 2502656 323 1283457024 134512640 136120023 4294765024 18446744073709551615 135511805 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 611 323 141 393 0 216 0

[startup+0.145802 s]
/proc/loadavg: 1.32 1.14 1.06 5/39 431
/proc/meminfo: memFree=371040/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=7840 CPUtime=0.14
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 1730 0 0 0 14 0 0 0 25 0 1 0 900571909 8028160 1670 1283457024 134512640 136120023 4294765024 18446744073709551615 134732349 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 1960 1670 141 393 0 1565 0
Current children cumulated CPU time (s) 0.14
Current children cumulated vsize (KiB) 10412

[startup+0.205815 s]
/proc/loadavg: 1.32 1.14 1.06 5/39 431
/proc/meminfo: memFree=371040/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=10104 CPUtime=0.2
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 2283 0 0 0 19 1 0 0 25 0 1 0 900571909 10346496 2223 1283457024 134512640 136120023 4294765024 18446744073709551615 135528598 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 2526 2223 141 393 0 2131 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12676

[startup+0.305839 s]
/proc/loadavg: 1.32 1.14 1.06 5/39 431
/proc/meminfo: memFree=371040/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=13600 CPUtime=0.3
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 3163 0 0 0 28 2 0 0 25 0 1 0 900571909 13926400 3103 1283457024 134512640 136120023 4294765024 18446744073709551615 134721204 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 3400 3103 142 393 0 3005 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16172

[startup+0.705931 s]
/proc/loadavg: 1.32 1.14 1.06 5/39 431
/proc/meminfo: memFree=371040/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=25412 CPUtime=0.7
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 6113 0 0 0 64 6 0 0 25 0 1 0 900571909 26021888 6053 1283457024 134512640 136120023 4294765024 18446744073709551615 135509298 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 6353 6053 142 393 0 5958 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 27984

[startup+1.50619 s]
/proc/loadavg: 1.32 1.14 1.06 2/40 432
/proc/meminfo: memFree=316576/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=56856 CPUtime=1.5
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 14130 0 0 0 140 10 0 0 25 0 1 0 900571909 58220544 13959 1283457024 134512640 136120023 4294765024 18446744073709551615 134863405 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 14214 13959 181 393 0 13819 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 59428

[startup+3.10652 s]
/proc/loadavg: 1.32 1.14 1.06 2/40 432
/proc/meminfo: memFree=316452/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=56856 CPUtime=3.1
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 14130 0 0 0 300 10 0 0 25 0 1 0 900571909 58220544 13959 1283457024 134512640 136120023 4294765024 18446744073709551615 134870868 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 14214 13959 181 393 0 13819 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 59428

[startup+6.30742 s]
/proc/loadavg: 1.30 1.14 1.06 2/40 432
/proc/meminfo: memFree=314840/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=58484 CPUtime=6.28
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 14549 0 0 0 618 10 0 0 25 0 1 0 900571909 59887616 14358 1283457024 134512640 136120023 4294765024 18446744073709551615 134831637 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 14621 14358 185 393 0 14226 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 61056

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

[startup+6.40745 s]
/proc/loadavg: 1.30 1.14 1.06 2/40 432
/proc/meminfo: memFree=314840/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=58484 CPUtime=6.38
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 14549 0 0 0 628 10 0 0 25 0 1 0 900571909 59887616 14358 1283457024 134512640 136120023 4294765024 18446744073709551615 134867751 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 14621 14358 185 393 0 14226 0
Current children cumulated CPU time (s) 6.38
Current children cumulated vsize (KiB) 61056

[startup+6.80756 s]
/proc/loadavg: 1.30 1.14 1.06 2/40 432
/proc/meminfo: memFree=314840/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=58484 CPUtime=6.78
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 14549 0 0 0 668 10 0 0 25 0 1 0 900571909 59887616 14358 1283457024 134512640 136120023 4294765024 18446744073709551615 134870671 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 14621 14358 185 393 0 14226 0
Current children cumulated CPU time (s) 6.78
Current children cumulated vsize (KiB) 61056

[startup+6.90766 s]
/proc/loadavg: 1.30 1.14 1.06 2/40 432
/proc/meminfo: memFree=314840/1048576 swapFree=2095372/2097144
[pid=430] ppid=429 vsize=2572 CPUtime=0
/proc/430/stat : 430 (cudf2msu4user-1) S 429 430 25521 34816 25544 4202496 380 0 0 0 0 0 0 0 18 0 1 0 900571909 2633728 277 1283457024 134512640 135304128 4292796384 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/430/statm: 643 277 237 194 0 29 0
[pid=431] ppid=430 vsize=58484 CPUtime=6.88
/proc/431/stat : 431 (cudf_msu32) R 430 430 25521 34816 25544 4202496 14549 0 0 0 678 10 0 0 25 0 1 0 900571909 59887616 14358 1283457024 134512640 136120023 4294765024 18446744073709551615 135524180 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/431/statm: 14621 14358 185 393 0 14226 0
Current children cumulated CPU time (s) 6.88
Current children cumulated vsize (KiB) 61056

Child status: 0
Real time (s): 6.99824
CPU time (s): 6.98044
CPU user time (s): 6.86843
CPU system time (s): 0.112007
CPU usage (%): 99.7456
Max. virtual memory (cumulated for all children) (KiB): 61056

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

runsolver used 0 second user time and 0 second system time

The end