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/201012070034/aptitude-trendy-1.0/2f690324-4939-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/debian-dudf//2f690324-4939-11df-9e6e-00163e7a6f5e.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/2f690324-4939-11df-9e6e-00163e7a6f5e.cudf.debian-dudf.result 

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.00 1.00 1.00 4/41 16009
/proc/meminfo: memFree=753888/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0
/proc/16001/stat : 16001 (aptitude-trendy) R 16000 16001 4159 34819 4229 4202496 493 1361 0 0 0 0 0 0 25 0 1 0 880488531 2646016 280 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/16001/statm: 646 280 237 194 0 32 0
[pid=16009] ppid=16001 vsize=2584 CPUtime=0
/proc/16009/stat : 16009 (aptitude-trendy) R 16001 16001 4159 34819 4229 4202560 0 0 0 0 0 0 0 0 25 0 1 0 880488532 2646016 43 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/16009/statm: 646 43 0 194 0 32 0

[startup+0.148571 s]
/proc/loadavg: 1.00 1.00 1.00 4/41 16009
/proc/meminfo: memFree=753888/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) R 16000 16001 4159 34819 4229 4202496 539 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65538 4 65536 0 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.208585 s]
/proc/loadavg: 1.00 1.00 1.00 4/41 16009
/proc/meminfo: memFree=753888/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 557 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.308615 s]
/proc/loadavg: 1.00 1.00 1.00 4/41 16009
/proc/meminfo: memFree=753888/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 557 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+0.708742 s]
/proc/loadavg: 1.00 1.00 1.00 4/41 16009
/proc/meminfo: memFree=753888/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 557 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
Current children cumulated CPU time (s) 0.04
Current children cumulated vsize (KiB) 2584

[startup+1.50895 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 16012
/proc/meminfo: memFree=711668/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 557 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
[pid=16012] ppid=16001 vsize=30528 CPUtime=1.45
/proc/16012/stat : 16012 (cudftodeb.nativ) R 16001 16001 4159 34819 4229 4202496 7173 0 0 0 142 3 0 0 25 0 1 0 880488537 31260672 7100 1283457024 134512640 135004320 4294941264 18446744073709551615 134634488 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16012/statm: 7632 7100 225 121 0 7024 0
Current children cumulated CPU time (s) 1.49
Current children cumulated vsize (KiB) 33112

[startup+3.10937 s]
/proc/loadavg: 1.00 1.00 1.00 2/42 16012
/proc/meminfo: memFree=691704/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 557 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
[pid=16012] ppid=16001 vsize=58928 CPUtime=3.04
/proc/16012/stat : 16012 (cudftodeb.nativ) R 16001 16001 4159 34819 4229 4202496 14187 0 0 0 298 6 0 0 25 0 1 0 880488537 60342272 14114 1283457024 134512640 135004320 4294941264 18446744073709551615 134951348 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16012/statm: 14732 14114 225 121 0 14124 0
Current children cumulated CPU time (s) 3.08
Current children cumulated vsize (KiB) 61512

[startup+6.31031 s]
/proc/loadavg: 1.08 1.02 1.01 2/42 16012
/proc/meminfo: memFree=636028/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2584 CPUtime=0.04
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 557 1862 0 0 0 0 0 4 25 0 1 0 880488531 2646016 283 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 646 283 240 194 0 32 0
[pid=16012] ppid=16001 vsize=113484 CPUtime=6.24
/proc/16012/stat : 16012 (cudftodeb.nativ) R 16001 16001 4159 34819 4229 4202496 27562 0 0 0 608 16 0 0 25 0 1 0 880488537 116207616 27489 1283457024 134512640 135004320 4294941264 18446744073709551615 134949662 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16012/statm: 28371 27489 237 121 0 27763 0
Current children cumulated CPU time (s) 6.28
Current children cumulated vsize (KiB) 116068

[startup+12.7072 s]
/proc/loadavg: 1.15 1.03 1.01 2/42 16023
/proc/meminfo: memFree=659480/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2592 CPUtime=9.84
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 682 40688 0 1 0 0 950 34 18 0 1 0 880488531 2654208 294 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 648 294 249 194 0 34 0
[pid=16022] ppid=16001 vsize=108408 CPUtime=1.22
/proc/16022/stat : 16022 (aptitude) R 16001 16001 4159 34819 4229 4202496 6821 241 346 0 116 6 0 0 20 0 1 0 880489620 111009792 7007 1283457024 134512640 137933492 4294457168 18446744073709551615 4159237441 0 134217728 4096 0 0 0 0 17 0 0 0 0
/proc/16022/statm: 27102 7007 6913 836 0 64 0
Current children cumulated CPU time (s) 11.06
Current children cumulated vsize (KiB) 111000

[startup+25.5128 s]
/proc/loadavg: 1.12 1.03 1.01 2/42 16028
/proc/meminfo: memFree=568384/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2592 CPUtime=19.59
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 707 74360 0 363 0 0 1904 55 18 0 1 0 880488531 2654208 294 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 648 294 249 194 0 34 0
[pid=16028] ppid=16001 vsize=70792 CPUtime=3.75
/proc/16028/stat : 16028 (aptsolutions.na) R 16001 16001 4159 34819 4229 4202496 17149 0 0 0 367 8 0 0 25 0 1 0 880490706 72491008 17038 1283457024 134512640 134971616 4287238848 18446744073709551615 134964261 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16028/statm: 17698 17038 204 113 0 17100 0
Current children cumulated CPU time (s) 23.34
Current children cumulated vsize (KiB) 73384

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

[startup+25.6129 s]
/proc/loadavg: 1.12 1.03 1.01 2/42 16028
/proc/meminfo: memFree=568384/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2592 CPUtime=19.59
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 707 74360 0 363 0 0 1904 55 18 0 1 0 880488531 2654208 294 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 648 294 249 194 0 34 0
[pid=16028] ppid=16001 vsize=72528 CPUtime=3.85
/proc/16028/stat : 16028 (aptsolutions.na) R 16001 16001 4159 34819 4229 4202496 17559 0 0 0 377 8 0 0 25 0 1 0 880490706 74268672 17448 1283457024 134512640 134971616 4287238848 18446744073709551615 134953918 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16028/statm: 18132 17448 204 113 0 17534 0
Current children cumulated CPU time (s) 23.44
Current children cumulated vsize (KiB) 75120

[startup+26.4135 s]
/proc/loadavg: 1.12 1.03 1.01 2/42 16028
/proc/meminfo: memFree=546436/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2592 CPUtime=19.59
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 707 74360 0 363 0 0 1904 55 18 0 1 0 880488531 2654208 294 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 648 294 249 194 0 34 0
[pid=16028] ppid=16001 vsize=91924 CPUtime=4.64
/proc/16028/stat : 16028 (aptsolutions.na) R 16001 16001 4159 34819 4229 4202496 22283 0 0 0 451 13 0 0 25 0 1 0 880490706 94130176 22172 1283457024 134512640 134971616 4287238848 18446744073709551615 134917827 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16028/statm: 22981 22172 209 113 0 22383 0
Current children cumulated CPU time (s) 24.23
Current children cumulated vsize (KiB) 94516

[startup+26.6136 s]
/proc/loadavg: 1.12 1.03 1.01 2/42 16028
/proc/meminfo: memFree=546436/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2592 CPUtime=19.59
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 707 74360 0 363 0 0 1904 55 18 0 1 0 880488531 2654208 294 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 648 294 249 194 0 34 0
[pid=16028] ppid=16001 vsize=98792 CPUtime=4.84
/proc/16028/stat : 16028 (aptsolutions.na) R 16001 16001 4159 34819 4229 4202496 23675 0 0 0 470 14 0 0 25 0 1 0 880490706 101163008 23564 1283457024 134512640 134971616 4287238848 18446744073709551615 134907916 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16028/statm: 24698 23564 209 113 0 24100 0
Current children cumulated CPU time (s) 24.43
Current children cumulated vsize (KiB) 101384

[startup+26.7136 s]
/proc/loadavg: 1.12 1.03 1.01 2/42 16028
/proc/meminfo: memFree=546436/1048576 swapFree=2080272/2097144
[pid=16001] ppid=16000 vsize=2592 CPUtime=19.59
/proc/16001/stat : 16001 (aptitude-trendy) S 16000 16001 4159 34819 4229 4202496 707 74360 0 363 0 0 1904 55 18 0 1 0 880488531 2654208 294 1283457024 134512640 135304128 4292050720 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/16001/statm: 648 294 249 194 0 34 0
[pid=16028] ppid=16001 vsize=108596 CPUtime=4.95
/proc/16028/stat : 16028 (aptsolutions.na) R 16001 16001 4159 34819 4229 4202496 25395 0 0 0 480 15 0 0 25 0 1 0 880490706 111202304 25284 1283457024 134512640 134971616 4287238848 18446744073709551615 134908004 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/16028/statm: 27149 25284 209 113 0 26551 0
Current children cumulated CPU time (s) 24.54
Current children cumulated vsize (KiB) 111188

Child status: 0
Real time (s): 26.7407
CPU time (s): 24.5775
CPU user time (s): 23.8535
CPU system time (s): 0.724045
CPU usage (%): 91.9105
Max. virtual memory (cumulated for all children) (KiB): 148804

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 23.8535
system time used= 0.724045
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 100845
page faults= 363
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 207
involuntary context switches= 393

runsolver used 0 second user time and 0 second system time

The end