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/7e7e0b16-38a5-11df-b280-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./cudf2msu4user-1.0 /home/misc2010/data/2010/debian-dudf//7e7e0b16-38a5-11df-b280-00163e7a6f5e.cudf /home/misc2010/tmp/201012091434/cudf2msu4user-1.0/7e7e0b16-38a5-11df-b280-00163e7a6f5e.cudf.debian-dudf.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.03 1.00 1.00 4/39 30851
/proc/meminfo: memFree=400416/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=2044 CPUtime=0
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 266 0 0 0 0 0 0 0 25 0 1 0 900395956 2093056 204 1283457024 134512640 136120023 4288805888 18446744073709551615 134732295 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 511 204 140 393 0 116 0

[startup+0.135654 s]
/proc/loadavg: 1.03 1.00 1.00 4/39 30851
/proc/meminfo: memFree=400416/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=6972 CPUtime=0.13
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 1523 0 0 0 13 0 0 0 25 0 1 0 900395956 7139328 1461 1283457024 134512640 136120023 4288805888 18446744073709551615 134732575 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 1743 1461 140 393 0 1348 0
Current children cumulated CPU time (s) 0.13
Current children cumulated vsize (KiB) 9548

[startup+0.205679 s]
/proc/loadavg: 1.03 1.00 1.00 4/39 30851
/proc/meminfo: memFree=400416/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=9612 CPUtime=0.2
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 2165 0 0 0 20 0 0 0 25 0 1 0 900395956 9842688 2103 1283457024 134512640 136120023 4288805888 18446744073709551615 135169216 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 2403 2103 140 393 0 2008 0
Current children cumulated CPU time (s) 0.2
Current children cumulated vsize (KiB) 12188

[startup+0.305708 s]
/proc/loadavg: 1.03 1.00 1.00 4/39 30851
/proc/meminfo: memFree=400416/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=12736 CPUtime=0.3
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 2949 0 0 0 30 0 0 0 25 0 1 0 900395956 13041664 2887 1283457024 134512640 136120023 4288805888 18446744073709551615 134732264 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 3184 2887 141 393 0 2789 0
Current children cumulated CPU time (s) 0.3
Current children cumulated vsize (KiB) 15312

[startup+0.705816 s]
/proc/loadavg: 1.03 1.00 1.00 4/39 30851
/proc/meminfo: memFree=400416/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=23756 CPUtime=0.7
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 5689 0 0 0 69 1 0 0 25 0 1 0 900395956 24326144 5627 1283457024 134512640 136120023 4288805888 18446744073709551615 134712094 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 5939 5627 141 393 0 5544 0
Current children cumulated CPU time (s) 0.7
Current children cumulated vsize (KiB) 26332

[startup+1.50604 s]
/proc/loadavg: 1.03 1.00 1.00 2/40 30852
/proc/meminfo: memFree=369024/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=51232 CPUtime=1.5
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 12964 0 0 0 146 4 0 0 25 0 1 0 900395956 52461568 12509 1283457024 134512640 136120023 4288805888 18446744073709551615 135524872 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 12808 12509 153 393 0 12413 0
Current children cumulated CPU time (s) 1.5
Current children cumulated vsize (KiB) 53808

[startup+3.10642 s]
/proc/loadavg: 1.03 1.00 1.00 2/40 30852
/proc/meminfo: memFree=288052/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=113876 CPUtime=3.1
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 28792 0 0 0 300 10 0 0 25 0 1 0 900395956 116609024 28168 1283457024 134512640 136120023 4288805888 18446744073709551615 134869125 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28469 28168 181 393 0 28074 0
Current children cumulated CPU time (s) 3.1
Current children cumulated vsize (KiB) 116452

[startup+6.30739 s]
/proc/loadavg: 1.03 1.00 1.00 2/40 30852
/proc/meminfo: memFree=287928/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=113876 CPUtime=6.3
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 28792 0 0 0 620 10 0 0 25 0 1 0 900395956 116609024 28168 1283457024 134512640 136120023 4288805888 18446744073709551615 135526267 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28469 28168 181 393 0 28074 0
Current children cumulated CPU time (s) 6.3
Current children cumulated vsize (KiB) 116452

[startup+12.7091 s]
/proc/loadavg: 1.11 1.02 1.01 2/40 30852
/proc/meminfo: memFree=287308/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=115068 CPUtime=12.69
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 29148 0 0 0 1258 11 0 0 25 0 1 0 900395956 117829632 28506 1283457024 134512640 136120023 4288805888 18446744073709551615 134869763 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28767 28506 185 393 0 28372 0
Current children cumulated CPU time (s) 12.69
Current children cumulated vsize (KiB) 117644

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

[startup+12.8091 s]
/proc/loadavg: 1.11 1.02 1.01 2/40 30852
/proc/meminfo: memFree=287308/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=115068 CPUtime=12.79
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 29148 0 0 0 1268 11 0 0 25 0 1 0 900395956 117829632 28506 1283457024 134512640 136120023 4288805888 18446744073709551615 134831643 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28767 28506 185 393 0 28372 0
Current children cumulated CPU time (s) 12.79
Current children cumulated vsize (KiB) 117644

[startup+13.2092 s]
/proc/loadavg: 1.10 1.02 1.00 2/40 30852
/proc/meminfo: memFree=287060/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=115068 CPUtime=13.19
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 29148 0 0 0 1308 11 0 0 25 0 1 0 900395956 117829632 28506 1283457024 134512640 136120023 4288805888 18446744073709551615 134862427 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28767 28506 185 393 0 28372 0
Current children cumulated CPU time (s) 13.19
Current children cumulated vsize (KiB) 117644

[startup+13.4093 s]
/proc/loadavg: 1.10 1.02 1.00 2/40 30852
/proc/meminfo: memFree=287060/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=115068 CPUtime=13.39
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 29148 0 0 0 1328 11 0 0 25 0 1 0 900395956 117829632 28506 1283457024 134512640 136120023 4288805888 18446744073709551615 135521304 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28767 28506 185 393 0 28372 0
Current children cumulated CPU time (s) 13.39
Current children cumulated vsize (KiB) 117644

[startup+13.5093 s]
/proc/loadavg: 1.10 1.02 1.00 2/40 30852
/proc/meminfo: memFree=287060/1048576 swapFree=2095372/2097144
[pid=30850] ppid=30849 vsize=2576 CPUtime=0
/proc/30850/stat : 30850 (cudf2msu4user-1) S 30849 30850 25521 34816 25544 4202496 382 0 0 0 0 0 0 0 18 0 1 0 900395956 2637824 277 1283457024 134512640 135304128 4288021264 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/30850/statm: 644 277 237 194 0 30 0
[pid=30851] ppid=30850 vsize=114872 CPUtime=13.49
/proc/30851/stat : 30851 (cudf_msu32) R 30850 30850 25521 34816 25544 4202496 29163 0 0 0 1335 14 0 0 25 0 1 0 900395956 117628928 28472 1283457024 134512640 136120023 4288805888 18446744073709551615 135511805 0 0 0 16929 0 0 0 17 0 0 0 0
/proc/30851/statm: 28718 28472 200 393 0 28323 0
Current children cumulated CPU time (s) 13.49
Current children cumulated vsize (KiB) 117448

Child status: 0
Real time (s): 13.5629
CPU time (s): 13.5488
CPU user time (s): 13.3848
CPU system time (s): 0.16401
CPU usage (%): 99.8963
Max. virtual memory (cumulated for all children) (KiB): 117644

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

runsolver used 0 second user time and 0 second system time

The end