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/rand7b4167.cudf.difficult.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/difficult//rand7b4167.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/rand7b4167.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.15 1.14 1.07 5/39 30034
/proc/meminfo: memFree=349132/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=2596 CPUtime=0.02
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 397 0 0 0 2 0 0 0 25 0 1 0 900191310 2658304 336 1283457024 134512640 136120023 4289684752 18446744073709551615 134722688 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 649 336 141 393 0 254 0

[startup+0.185828 s]
/proc/loadavg: 1.15 1.14 1.07 5/39 30034
/proc/meminfo: memFree=349132/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=9556 CPUtime=0.19
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 2168 0 0 0 17 2 0 0 25 0 1 0 900191310 9785344 2107 1283457024 134512640 136120023 4289684752 18446744073709551615 134712388 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 2389 2107 141 393 0 1994 0
Current children cumulated CPU time (s) 0.19
Current children cumulated vsize (KiB) 12128

[startup+0.205829 s]
/proc/loadavg: 1.15 1.14 1.07 5/39 30034
/proc/meminfo: memFree=349132/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=10236 CPUtime=0.21
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 2333 0 0 0 19 2 0 0 25 0 1 0 900191310 10481664 2272 1283457024 134512640 136120023 4289684752 18446744073709551615 135296895 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 2559 2272 141 393 0 2164 0
Current children cumulated CPU time (s) 0.21
Current children cumulated vsize (KiB) 12808

[startup+0.305849 s]
/proc/loadavg: 1.15 1.14 1.07 5/39 30034
/proc/meminfo: memFree=349132/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=13864 CPUtime=0.31
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 3230 0 0 0 29 2 0 0 25 0 1 0 900191310 14196736 3169 1283457024 134512640 136120023 4289684752 18446744073709551615 135021888 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 3466 3169 142 393 0 3071 0
Current children cumulated CPU time (s) 0.31
Current children cumulated vsize (KiB) 16436

[startup+0.705912 s]
/proc/loadavg: 1.15 1.14 1.07 5/39 30034
/proc/meminfo: memFree=349132/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=25808 CPUtime=0.71
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 6220 0 0 0 69 2 0 0 25 0 1 0 900191310 26427392 6159 1283457024 134512640 136120023 4289684752 18446744073709551615 134711787 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 6452 6159 142 393 0 6057 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 28380

[startup+1.50609 s]
/proc/loadavg: 1.15 1.14 1.07 2/40 30035
/proc/meminfo: memFree=294976/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=56512 CPUtime=1.5
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 14038 0 0 0 148 2 0 0 25 0 1 0 900191310 57868288 13866 1283457024 134512640 136120023 4289684752 18446744073709551615 134859209 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 14128 13866 181 393 0 13733 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 59084

[startup+3.10641 s]
/proc/loadavg: 1.15 1.14 1.07 2/40 30035
/proc/meminfo: memFree=294852/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=56936 CPUtime=3.1
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 14167 0 0 0 308 2 0 0 25 0 1 0 900191310 58302464 13982 1283457024 134512640 136120023 4289684752 18446744073709551615 134869710 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 14234 13982 185 393 0 13839 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 59508

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

[startup+3.20642 s]
/proc/loadavg: 1.15 1.14 1.07 2/40 30035
/proc/meminfo: memFree=294852/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=56936 CPUtime=3.2
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 14167 0 0 0 318 2 0 0 25 0 1 0 900191310 58302464 13982 1283457024 134512640 136120023 4289684752 18446744073709551615 134870411 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 14234 13982 185 393 0 13839 0
Current children cumulated CPU time (s) 3.2
Current children cumulated vsize (KiB) 59508

[startup+4.00654 s]
/proc/loadavg: 1.15 1.14 1.07 2/40 30035
/proc/meminfo: memFree=294480/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=57336 CPUtime=4
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 14251 0 0 0 398 2 0 0 25 0 1 0 900191310 58712064 14060 1283457024 134512640 136120023 4289684752 18446744073709551615 134831738 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 14334 14060 185 393 0 13939 0
Current children cumulated CPU time (s) 4
Current children cumulated vsize (KiB) 59908

[startup+4.40777 s]
/proc/loadavg: 1.15 1.14 1.07 2/40 30035
/proc/meminfo: memFree=293612/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=57824 CPUtime=4.4
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 14418 0 0 0 438 2 0 0 25 0 1 0 900191310 59211776 14187 1283457024 134512640 136120023 4289684752 18446744073709551615 134867708 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 14456 14187 185 393 0 14061 0
Current children cumulated CPU time (s) 4.4
Current children cumulated vsize (KiB) 60396

[startup+4.80783 s]
/proc/loadavg: 1.15 1.14 1.07 2/40 30035
/proc/meminfo: memFree=293612/1048576 swapFree=2095372/2097144
[pid=30033] ppid=30032 vsize=2572 CPUtime=0
/proc/30033/stat : 30033 (cudf2msu4user-1) S 30032 30033 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900191310 2633728 277 1283457024 134512640 135304128 4287847200 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30033/statm: 643 277 237 194 0 29 0
[pid=30034] ppid=30033 vsize=57824 CPUtime=4.79
/proc/30034/stat : 30034 (cudf_msu32) R 30033 30033 25521 34816 25544 4202496 14418 0 0 0 477 2 0 0 25 0 1 0 900191310 59211776 14187 1283457024 134512640 136120023 4289684752 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30034/statm: 14456 14187 185 393 0 14061 0
Current children cumulated CPU time (s) 4.79
Current children cumulated vsize (KiB) 60396

Child status: 0
Real time (s): 4.88803
CPU time (s): 4.88431
CPU user time (s): 4.8363
CPU system time (s): 0.048003
CPU usage (%): 99.9238
Max. virtual memory (cumulated for all children) (KiB): 60396

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

runsolver used 0 second user time and 0 second system time

The end