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/randa651ed.cudf.difficult.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/difficult//randa651ed.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/randa651ed.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.02 1.04 1.02 4/39 32431
/proc/meminfo: memFree=415128/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=2048 CPUtime=0.01
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 272 0 0 0 1 0 0 0 25 0 1 0 900561926 2097152 211 1283457024 134512640 136120023 4293974304 18446744073709551615 134712344 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 512 211 140 393 0 117 0

[startup+0.165699 s]
/proc/loadavg: 1.02 1.04 1.02 4/39 32431
/proc/meminfo: memFree=415128/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=8896 CPUtime=0.17
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 1972 0 0 0 17 0 0 0 25 0 1 0 900561926 9109504 1911 1283457024 134512640 136120023 4293974304 18446744073709551615 134732295 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 2224 1911 141 393 0 1829 0
Current children cumulated CPU time (s) 0.17
Current children cumulated vsize (KiB) 11468

[startup+0.205705 s]
/proc/loadavg: 1.02 1.04 1.02 4/39 32431
/proc/meminfo: memFree=415128/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=10236 CPUtime=0.21
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 2329 0 0 0 21 0 0 0 25 0 1 0 900561926 10481664 2268 1283457024 134512640 136120023 4293974304 18446744073709551615 134578235 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 2559 2268 141 393 0 2164 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12808

[startup+0.305718 s]
/proc/loadavg: 1.02 1.04 1.02 4/39 32431
/proc/meminfo: memFree=415128/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=13864 CPUtime=0.31
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 3228 0 0 0 31 0 0 0 25 0 1 0 900561926 14196736 3167 1283457024 134512640 136120023 4293974304 18446744073709551615 135530288 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 3466 3167 142 393 0 3071 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16436

[startup+0.705775 s]
/proc/loadavg: 1.02 1.04 1.02 4/39 32431
/proc/meminfo: memFree=415128/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=25808 CPUtime=0.71
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 6215 0 0 0 71 0 0 0 25 0 1 0 900561926 26427392 6154 1283457024 134512640 136120023 4293974304 18446744073709551615 134732506 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 6452 6154 142 393 0 6057 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 28380

[startup+1.50597 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=360920/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=56220 CPUtime=1.51
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 13949 0 0 0 151 0 0 0 25 0 1 0 900561926 57569280 13777 1283457024 134512640 136120023 4293974304 18446744073709551615 135511683 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14055 13777 181 393 0 13660 0
Current children cumulated CPU time (s) 1.51
Current children cumulated vsize (KiB) 58792

[startup+3.10635 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=360796/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=56220 CPUtime=3.11
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 13949 0 0 0 311 0 0 0 25 0 1 0 900561926 57569280 13777 1283457024 134512640 136120023 4293974304 18446744073709551615 134863525 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14055 13777 181 393 0 13660 0
Current children cumulated CPU time (s) 3.11
Current children cumulated vsize (KiB) 58792

[startup+6.30727 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=358812/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=58060 CPUtime=6.31
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 14551 0 0 0 631 0 0 0 25 0 1 0 900561926 59453440 14259 1283457024 134512640 136120023 4293974304 18446744073709551615 134837904 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14515 14259 185 393 0 14120 0
Current children cumulated CPU time (s) 6.31
Current children cumulated vsize (KiB) 60632

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

[startup+6.4073 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=358812/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=58060 CPUtime=6.41
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 14551 0 0 0 641 0 0 0 25 0 1 0 900561926 59453440 14259 1283457024 134512640 136120023 4293974304 18446744073709551615 134862045 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14515 14259 185 393 0 14120 0
Current children cumulated CPU time (s) 6.41
Current children cumulated vsize (KiB) 60632

[startup+6.80741 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=358812/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=58060 CPUtime=6.81
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 14551 0 0 0 681 0 0 0 25 0 1 0 900561926 59453440 14259 1283457024 134512640 136120023 4293974304 18446744073709551615 134872772 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14515 14259 185 393 0 14120 0
Current children cumulated CPU time (s) 6.81
Current children cumulated vsize (KiB) 60632

[startup+7.20753 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=358812/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=58060 CPUtime=7.21
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 14551 0 0 0 721 0 0 0 25 0 1 0 900561926 59453440 14259 1283457024 134512640 136120023 4293974304 18446744073709551615 135511884 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14515 14259 185 393 0 14120 0
Current children cumulated CPU time (s) 7.21
Current children cumulated vsize (KiB) 60632

[startup+7.30755 s]
/proc/loadavg: 1.02 1.04 1.02 2/40 32432
/proc/meminfo: memFree=358812/1048576 swapFree=2095372/2097144
[pid=32430] ppid=32429 vsize=2572 CPUtime=0
/proc/32430/stat : 32430 (cudf2msu4user-1) S 32429 32430 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900561926 2633728 277 1283457024 134512640 135304128 4292058928 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32430/statm: 643 277 237 194 0 29 0
[pid=32431] ppid=32430 vsize=56728 CPUtime=7.31
/proc/32431/stat : 32431 (cudf_msu32) R 32430 32430 25521 34816 25544 4202496 14551 0 0 0 731 0 0 0 25 0 1 0 900561926 58089472 13944 1283457024 134512640 136120023 4293974304 18446744073709551615 134892886 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32431/statm: 14182 13944 185 393 0 13787 0
Current children cumulated CPU time (s) 7.31
Current children cumulated vsize (KiB) 59300

Child status: 0
Real time (s): 7.37186
CPU time (s): 7.37246
CPU user time (s): 7.36446
CPU system time (s): 0.008
CPU usage (%): 100.008
Max. virtual memory (cumulated for all children) (KiB): 60632

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

runsolver used 0 second user time and 0 second system time

The end