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/rand95e48b.cudf.difficult.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/difficult//rand95e48b.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/rand95e48b.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.03 1.00 4/39 31440
/proc/meminfo: memFree=378836/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=2044 CPUtime=0.01
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 266 0 0 0 1 0 0 0 25 0 1 0 900456039 2093056 205 1283457024 134512640 136120023 4294259040 18446744073709551615 134732925 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 511 205 140 393 0 116 0

[startup+0.155422 s]
/proc/loadavg: 1.02 1.03 1.00 4/39 31440
/proc/meminfo: memFree=378836/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=8364 CPUtime=0.15
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 1859 0 0 0 13 2 0 0 25 0 1 0 900456039 8564736 1798 1283457024 134512640 136120023 4294259040 18446744073709551615 134732391 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 2091 1798 141 393 0 1696 0
Current children cumulated CPU time (s) 0.15
Current children cumulated vsize (KiB) 10936

[startup+0.205433 s]
/proc/loadavg: 1.02 1.03 1.00 4/39 31440
/proc/meminfo: memFree=378836/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=10232 CPUtime=0.2
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 2312 0 0 0 18 2 0 0 25 0 1 0 900456039 10477568 2251 1283457024 134512640 136120023 4294259040 18446744073709551615 135163955 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 2558 2251 141 393 0 2163 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12804

[startup+0.305462 s]
/proc/loadavg: 1.02 1.03 1.00 4/39 31440
/proc/meminfo: memFree=378836/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=13728 CPUtime=0.3
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 3186 0 0 0 28 2 0 0 25 0 1 0 900456039 14057472 3125 1283457024 134512640 136120023 4294259040 18446744073709551615 134733573 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 3432 3125 142 393 0 3037 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16300

[startup+0.705537 s]
/proc/loadavg: 1.02 1.03 1.00 4/39 31440
/proc/meminfo: memFree=378836/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=25540 CPUtime=0.7
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 6150 0 0 0 67 3 0 0 25 0 1 0 900456039 26152960 6089 1283457024 134512640 136120023 4294259040 18446744073709551615 134711773 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 6385 6089 142 393 0 5990 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 28112

[startup+1.50575 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31441
/proc/meminfo: memFree=323636/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=57056 CPUtime=1.5
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14175 0 0 0 143 7 0 0 25 0 1 0 900456039 58425344 14003 1283457024 134512640 136120023 4294259040 18446744073709551615 134849225 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14264 14003 181 393 0 13869 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 59628

[startup+3.10614 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31441
/proc/meminfo: memFree=323636/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=57056 CPUtime=3.1
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14175 0 0 0 303 7 0 0 25 0 1 0 900456039 58425344 14003 1283457024 134512640 136120023 4294259040 18446744073709551615 134840764 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14264 14003 181 393 0 13869 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 59628

[startup+6.30702 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31441
/proc/meminfo: memFree=322148/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=58968 CPUtime=6.3
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14803 0 0 0 623 7 0 0 25 0 1 0 900456039 60383232 14500 1283457024 134512640 136120023 4294259040 18446744073709551615 134863191 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14742 14500 185 393 0 14347 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 61540

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

[startup+6.40705 s]
/proc/loadavg: 1.02 1.03 1.00 2/40 31441
/proc/meminfo: memFree=322148/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=58968 CPUtime=6.4
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14803 0 0 0 633 7 0 0 25 0 1 0 900456039 60383232 14500 1283457024 134512640 136120023 4294259040 18446744073709551615 134831637 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14742 14500 185 393 0 14347 0
Current children cumulated CPU time (s) 6.4
Current children cumulated vsize (KiB) 61540

[startup+8.00752 s]
/proc/loadavg: 1.01 1.03 1.00 2/40 31441
/proc/meminfo: memFree=321528/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=58968 CPUtime=8
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14803 0 0 0 792 8 0 0 25 0 1 0 900456039 60383232 14500 1283457024 134512640 136120023 4294259040 18446744073709551615 135521140 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14742 14500 185 393 0 14347 0
Current children cumulated CPU time (s) 8
Current children cumulated vsize (KiB) 61540

[startup+8.40762 s]
/proc/loadavg: 1.01 1.03 1.00 2/40 31441
/proc/meminfo: memFree=321528/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=58968 CPUtime=8.4
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14803 0 0 0 832 8 0 0 25 0 1 0 900456039 60383232 14500 1283457024 134512640 136120023 4294259040 18446744073709551615 134868665 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14742 14500 185 393 0 14347 0
Current children cumulated CPU time (s) 8.4
Current children cumulated vsize (KiB) 61540

[startup+8.80773 s]
/proc/loadavg: 1.01 1.03 1.00 2/40 31441
/proc/meminfo: memFree=321528/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=58968 CPUtime=8.8
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202496 14803 0 0 0 871 9 0 0 25 0 1 0 900456039 60383232 14500 1283457024 134512640 136120023 4294259040 18446744073709551615 134837910 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 14742 14500 185 393 0 14347 0
Current children cumulated CPU time (s) 8.8
Current children cumulated vsize (KiB) 61540

[startup+8.90779 s]
/proc/loadavg: 1.01 1.03 1.00 2/40 31441
/proc/meminfo: memFree=321528/1048576 swapFree=2095372/2097144
[pid=31439] ppid=31438 vsize=2572 CPUtime=0
/proc/31439/stat : 31439 (cudf2msu4user-1) S 31438 31439 25521 34816 25544 4202496 381 0 0 0 0 0 0 0 18 0 1 0 900456039 2633728 277 1283457024 134512640 135304128 4294447472 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/31439/statm: 643 277 237 194 0 29 0
[pid=31440] ppid=31439 vsize=0 CPUtime=8.89
/proc/31440/stat : 31440 (cudf_msu32) R 31439 31439 25521 34816 25544 4202500 14819 0 0 0 878 11 0 0 25 0 1 0 900456039 0 0 1283457024 0 0 0 0 0 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/31440/statm: 0 0 0 0 0 0 0
Current children cumulated CPU time (s) 8.89
Current children cumulated vsize (KiB) 2572

Child status: 0
Real time (s): 8.91029
CPU time (s): 8.89655
CPU user time (s): 8.78055
CPU system time (s): 0.116007
CPU usage (%): 99.8458
Max. virtual memory (cumulated for all children) (KiB): 61540

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

runsolver used 0 second user time and 0 second system time

The end