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/randec88d5.cudf.impossible.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/impossible//randec88d5.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/randec88d5.cudf.impossible.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.06 1.09 1.05 5/39 32197
/proc/meminfo: memFree=446164/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=2708 CPUtime=0.01
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 435 0 0 0 1 0 0 0 25 0 1 0 900527708 2772992 373 1283457024 134512640 136120023 4287648528 18446744073709551615 135528598 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 677 373 140 393 0 282 0

[startup+0.22825 s]
/proc/loadavg: 1.06 1.09 1.05 5/39 32197
/proc/meminfo: memFree=446164/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=10740 CPUtime=0.22
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 2450 0 0 0 22 0 0 0 25 0 1 0 900527708 10997760 2388 1283457024 134512640 136120023 4287648528 18446744073709551615 135288691 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 2685 2388 142 393 0 2290 0
Current children cumulated CPU time (s) 0.22
Current children cumulated vsize (KiB) 13312

[startup+0.308254 s]
/proc/loadavg: 1.06 1.09 1.05 5/39 32197
/proc/meminfo: memFree=446164/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=13512 CPUtime=0.3
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 3144 0 0 0 30 0 0 0 25 0 1 0 900527708 13836288 3082 1283457024 134512640 136120023 4287648528 18446744073709551615 134732539 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 3378 3082 142 393 0 2983 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 16084

[startup+0.408271 s]
/proc/loadavg: 1.06 1.09 1.05 5/39 32197
/proc/meminfo: memFree=446164/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=16680 CPUtime=0.4
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 3943 0 0 0 40 0 0 0 25 0 1 0 900527708 17080320 3881 1283457024 134512640 136120023 4287648528 18446744073709551615 135538956 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 4170 3881 142 393 0 3775 0
Current children cumulated CPU time (s) 0.4
Current children cumulated vsize (KiB) 19252

[startup+0.708366 s]
/proc/loadavg: 1.06 1.09 1.05 5/39 32197
/proc/meminfo: memFree=446164/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=25324 CPUtime=0.71
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 6089 0 0 0 69 2 0 0 25 0 1 0 900527708 25931776 6027 1283457024 134512640 136120023 4287648528 18446744073709551615 134711981 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 6331 6027 142 393 0 5936 0
Current children cumulated CPU time (s) 0.71
Current children cumulated vsize (KiB) 27896

[startup+1.50854 s]
/proc/loadavg: 1.05 1.09 1.05 2/40 32198
/proc/meminfo: memFree=410608/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=45448 CPUtime=1.5
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 11164 0 0 0 146 4 0 0 25 0 1 0 900527708 46538752 11053 1283457024 134512640 136120023 4287648528 18446744073709551615 135545164 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 11362 11053 142 393 0 10967 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 48020

[startup+3.10888 s]
/proc/loadavg: 1.05 1.09 1.05 2/40 32198
/proc/meminfo: memFree=316988/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=140372 CPUtime=3.1
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 35415 0 0 0 297 13 0 0 25 0 1 0 900527708 143740928 34812 1283457024 134512640 136120023 4287648528 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35093 34812 179 393 0 34698 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 142944

[startup+6.30964 s]
/proc/loadavg: 1.05 1.09 1.05 2/40 32198
/proc/meminfo: memFree=307564/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=140372 CPUtime=6.3
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 35417 0 0 0 616 14 0 0 25 0 1 0 900527708 143740928 34814 1283457024 134512640 136120023 4287648528 18446744073709551615 135511868 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35093 34814 181 393 0 34698 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 142944

[startup+12.7118 s]
/proc/loadavg: 1.04 1.09 1.05 2/40 32198
/proc/meminfo: memFree=307564/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=140372 CPUtime=12.7
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 35417 0 0 0 1256 14 0 0 25 0 1 0 900527708 143740928 34814 1283457024 134512640 136120023 4287648528 18446744073709551615 134862106 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35093 34814 181 393 0 34698 0
Current children cumulated CPU time (s) 12.7
Current children cumulated vsize (KiB) 142944

[startup+25.5055 s]
/proc/loadavg: 1.04 1.08 1.05 2/40 32198
/proc/meminfo: memFree=305828/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142604 CPUtime=25.48
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36853 0 0 0 2532 16 0 0 25 0 1 0 900527708 146026496 35384 1283457024 134512640 136120023 4287648528 18446744073709551615 134866659 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35651 35384 185 393 0 35256 0
Current children cumulated CPU time (s) 25.48
Current children cumulated vsize (KiB) 145176

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

[startup+25.7056 s]
/proc/loadavg: 1.04 1.08 1.05 2/40 32198
/proc/meminfo: memFree=305828/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142604 CPUtime=25.67
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36853 0 0 0 2551 16 0 0 25 0 1 0 900527708 146026496 35384 1283457024 134512640 136120023 4287648528 18446744073709551615 135545100 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35651 35384 185 393 0 35256 0
Current children cumulated CPU time (s) 25.67
Current children cumulated vsize (KiB) 145176

[startup+28.9063 s]
/proc/loadavg: 1.03 1.08 1.04 2/40 32198
/proc/meminfo: memFree=305704/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142604 CPUtime=28.87
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36853 0 0 0 2871 16 0 0 25 0 1 0 900527708 146026496 35384 1283457024 134512640 136120023 4287648528 18446744073709551615 134839968 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35651 35384 185 393 0 35256 0
Current children cumulated CPU time (s) 28.87
Current children cumulated vsize (KiB) 145176

[startup+29.7065 s]
/proc/loadavg: 1.03 1.08 1.04 2/40 32198
/proc/meminfo: memFree=305704/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142604 CPUtime=29.67
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36853 0 0 0 2951 16 0 0 25 0 1 0 900527708 146026496 35384 1283457024 134512640 136120023 4287648528 18446744073709551615 134870961 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35651 35384 185 393 0 35256 0
Current children cumulated CPU time (s) 29.67
Current children cumulated vsize (KiB) 145176

[startup+30.1065 s]
/proc/loadavg: 1.03 1.08 1.04 2/40 32198
/proc/meminfo: memFree=305704/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142604 CPUtime=30.07
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36853 0 0 0 2991 16 0 0 25 0 1 0 900527708 146026496 35384 1283457024 134512640 136120023 4287648528 18446744073709551615 134867555 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35651 35384 185 393 0 35256 0
Current children cumulated CPU time (s) 30.07
Current children cumulated vsize (KiB) 145176

[startup+30.5066 s]
/proc/loadavg: 1.03 1.08 1.04 2/40 32198
/proc/meminfo: memFree=305704/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142604 CPUtime=30.47
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36853 0 0 0 3031 16 0 0 25 0 1 0 900527708 146026496 35384 1283457024 134512640 136120023 4287648528 18446744073709551615 134840174 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35651 35384 185 393 0 35256 0
Current children cumulated CPU time (s) 30.47
Current children cumulated vsize (KiB) 145176

[startup+30.6066 s]
/proc/loadavg: 1.03 1.08 1.04 2/40 32198
/proc/meminfo: memFree=305704/1048576 swapFree=2095372/2097144
[pid=32196] ppid=32195 vsize=2572 CPUtime=0
/proc/32196/stat : 32196 (cudf2msu4user-1) S 32195 32196 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900527708 2633728 278 1283457024 134512640 135304128 4289492144 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/32196/statm: 643 278 237 194 0 29 0
[pid=32197] ppid=32196 vsize=142408 CPUtime=30.57
/proc/32197/stat : 32197 (cudf_msu32) R 32196 32196 25521 34816 25544 4202496 36868 0 0 0 3041 16 0 0 25 0 1 0 900527708 145825792 35350 1283457024 134512640 136120023 4287648528 18446744073709551615 134576071 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/32197/statm: 35602 35350 200 393 0 35207 0
Current children cumulated CPU time (s) 30.57
Current children cumulated vsize (KiB) 144980

Child status: 0
Real time (s): 30.6756
CPU time (s): 30.6379
CPU user time (s): 30.4579
CPU system time (s): 0.180011
CPU usage (%): 99.8773
Max. virtual memory (cumulated for all children) (KiB): 145176

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

runsolver used 0 second user time and 0 second system time

The end