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/randbe9acf.cudf.easy.log.runsolver ./aptitude-trendy-1.0 /home/misc2010/data/2010/easy//randbe9acf.cudf /home/misc2010/tmp/201012070034/aptitude-trendy-1.0/randbe9acf.cudf.easy.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: 0.89 0.97 0.99 2/40 5207
/proc/meminfo: memFree=848460/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=3028 CPUtime=0
/proc/5207/stat : 5207 (runsolver) D 5206 5207 4159 34819 4229 4202560 73 0 0 0 0 0 0 0 25 0 1 0 885408973 3100672 94 1283457024 134512640 134586868 4292859744 18446744073709551615 4294960130 0 0 0 24578 18446744071564332000 0 0 17 0 0 0 0
/proc/5207/statm: 757 94 62 19 0 55 0

[startup+0.194814 s]
/proc/loadavg: 0.89 0.97 0.99 2/40 5207
/proc/meminfo: memFree=848460/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2588 CPUtime=0.02
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 568 1863 0 0 0 0 0 2 25 0 1 0 885408973 2650112 284 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.210874 s]
/proc/loadavg: 0.89 0.97 0.99 2/40 5207
/proc/meminfo: memFree=848460/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2588 CPUtime=0.02
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 568 1863 0 0 0 0 0 2 25 0 1 0 885408973 2650112 284 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.310896 s]
/proc/loadavg: 0.89 0.97 0.99 2/40 5207
/proc/meminfo: memFree=848460/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2588 CPUtime=0.02
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 568 1863 0 0 0 0 0 2 25 0 1 0 885408973 2650112 284 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+0.710988 s]
/proc/loadavg: 0.89 0.97 0.99 2/40 5207
/proc/meminfo: memFree=848460/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2588 CPUtime=0.02
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 568 1863 0 0 0 0 0 2 25 0 1 0 885408973 2650112 284 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 647 284 240 194 0 33 0
Current children cumulated CPU time (s) 0.02
Current children cumulated vsize (KiB) 2588

[startup+1.51114 s]
/proc/loadavg: 0.89 0.97 0.99 2/42 5218
/proc/meminfo: memFree=816492/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2588 CPUtime=0.02
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 568 1863 0 0 0 0 0 2 25 0 1 0 885408973 2650112 284 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 647 284 240 194 0 33 0
[pid=5218] ppid=5207 vsize=33440 CPUtime=1.44
/proc/5218/stat : 5218 (cudftodeb.nativ) R 5207 5207 4159 34819 4229 4202496 7933 0 8 0 142 2 0 0 25 0 1 0 885408977 34242560 7867 1283457024 134512640 135004320 4289155760 18446744073709551615 134610615 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5218/statm: 8360 7867 225 121 0 7752 0
Current children cumulated CPU time (s) 1.46
Current children cumulated vsize (KiB) 36028

[startup+3.11135 s]
/proc/loadavg: 0.89 0.97 0.99 2/42 5218
/proc/meminfo: memFree=790576/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2588 CPUtime=0.02
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 568 1863 0 0 0 0 0 2 25 0 1 0 885408973 2650112 284 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 647 284 240 194 0 33 0
[pid=5218] ppid=5207 vsize=31480 CPUtime=3.05
/proc/5218/stat : 5218 (cudftodeb.nativ) R 5207 5207 4159 34819 4229 4202496 12305 0 8 0 297 8 0 0 25 0 1 0 885408977 32235520 7420 1283457024 134512640 135004320 4289155760 18446744073709551615 134946101 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5218/statm: 7870 7420 237 121 0 7262 0
Current children cumulated CPU time (s) 3.07
Current children cumulated vsize (KiB) 34068

[startup+6.31292 s]
/proc/loadavg: 0.98 0.99 0.99 1/42 5229
/proc/meminfo: memFree=786276/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2596 CPUtime=3.43
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 693 18002 0 9 0 0 328 15 16 0 1 0 885408973 2658304 295 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 649 295 249 194 0 35 0
[pid=5228] ppid=5207 vsize=49824 CPUtime=1.1
/proc/5228/stat : 5228 (aptitude) R 5207 5207 4159 34819 4229 4202496 10159 239 254 0 103 7 0 0 18 0 2 0 885409378 51019776 6715 1283457024 134512640 137933492 4288494528 18446744073709551615 4153421124 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/5228/statm: 12456 6715 4127 836 0 6672 0
Current children cumulated CPU time (s) 4.53
Current children cumulated vsize (KiB) 52420
heavy processes:

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

[startup+6.41293 s]
/proc/loadavg: 0.98 0.99 0.99 2/43 5231
/proc/meminfo: memFree=773048/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2596 CPUtime=3.43
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 693 18002 0 9 0 0 328 15 16 0 1 0 885408973 2658304 295 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 649 295 249 194 0 35 0
[pid=5228] ppid=5207 vsize=49824 CPUtime=1.2
/proc/5228/stat : 5228 (aptitude) R 5207 5207 4159 34819 4229 4202496 10162 239 254 0 113 7 0 0 18 0 2 0 885409378 51019776 6718 1283457024 134512640 137933492 4288494528 18446744073709551615 4154870324 0 134217728 4096 0 18446744073709551615 0 0 17 0 0 0 0
/proc/5228/statm: 12456 6718 4130 836 0 6672 0
[pid=5228/tid=5230] ppid=5207 vsize=49824 CPUtime=0
/proc/5228/task/5230/stat : 5230 (aptitude) S 5207 5207 4159 34819 4229 4202560 3 239 0 0 0 0 0 0 19 0 2 0 885409567 51019776 6718 1283457024 134512640 137933492 4288494528 18446744073709551615 4294960130 0 134217728 4096 0 18446612133393159168 0 0 -1 0 0 0 0
Current children cumulated CPU time (s) 4.63
Current children cumulated vsize (KiB) 52420

[startup+8.00708 s]
/proc/loadavg: 0.98 0.99 0.99 2/42 5234
/proc/meminfo: memFree=773328/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2596 CPUtime=5.45
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 721 31974 0 264 0 1 521 23 18 0 1 0 885408973 2658304 295 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 649 295 249 194 0 35 0
[pid=5234] ppid=5207 vsize=18016 CPUtime=0.7
/proc/5234/stat : 5234 (aptsolutions.na) R 5207 5207 4159 34819 4229 4202496 4159 0 9 0 70 0 0 0 20 0 1 0 885409698 18448384 4055 1283457024 134512640 134971616 4292327376 18446744073709551615 134914468 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5234/statm: 4504 4055 204 113 0 3906 0
Current children cumulated CPU time (s) 6.15
Current children cumulated vsize (KiB) 20612

[startup+8.40717 s]
/proc/loadavg: 0.98 0.99 0.99 2/42 5234
/proc/meminfo: memFree=773328/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2596 CPUtime=5.45
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 721 31974 0 264 0 1 521 23 18 0 1 0 885408973 2658304 295 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 649 295 249 194 0 35 0
[pid=5234] ppid=5207 vsize=26696 CPUtime=1.09
/proc/5234/stat : 5234 (aptsolutions.na) R 5207 5207 4159 34819 4229 4202496 6294 0 9 0 109 0 0 0 21 0 1 0 885409698 27336704 6190 1283457024 134512640 134971616 4292327376 18446744073709551615 134954119 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5234/statm: 6674 6190 204 113 0 6076 0
Current children cumulated CPU time (s) 6.54
Current children cumulated vsize (KiB) 29292

[startup+8.80728 s]
/proc/loadavg: 0.98 0.99 0.99 2/42 5234
/proc/meminfo: memFree=749272/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2596 CPUtime=5.45
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 721 31974 0 264 0 1 521 23 18 0 1 0 885408973 2658304 295 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 649 295 249 194 0 35 0
[pid=5234] ppid=5207 vsize=36324 CPUtime=1.49
/proc/5234/stat : 5234 (aptsolutions.na) R 5207 5207 4159 34819 4229 4202496 8653 0 9 0 148 1 0 0 22 0 1 0 885409698 37195776 8547 1283457024 134512640 134971616 4292327376 18446744073709551615 134915893 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5234/statm: 9081 8547 209 113 0 8483 0
Current children cumulated CPU time (s) 6.94
Current children cumulated vsize (KiB) 38920

[startup+8.90731 s]
/proc/loadavg: 0.98 0.99 0.99 2/42 5234
/proc/meminfo: memFree=749272/1048576 swapFree=2077620/2097144
[pid=5207] ppid=5206 vsize=2596 CPUtime=5.45
/proc/5207/stat : 5207 (aptitude-trendy) S 5206 5207 4159 34819 4229 4202496 721 31974 0 264 0 1 521 23 18 0 1 0 885408973 2658304 295 1283457024 134512640 135304128 4288369632 18446744073709551615 4294960130 0 65536 4 65538 18446744071564329979 0 0 17 0 0 0 0
/proc/5207/statm: 649 295 249 194 0 35 0
[pid=5234] ppid=5207 vsize=41800 CPUtime=1.59
/proc/5234/stat : 5234 (aptsolutions.na) R 5207 5207 4159 34819 4229 4202496 9979 0 9 0 158 1 0 0 23 0 1 0 885409698 42803200 9873 1283457024 134512640 134971616 4292327376 18446744073709551615 134838771 0 0 0 1024 0 0 0 17 0 0 0 0
/proc/5234/statm: 10450 9873 209 113 0 9852 0
Current children cumulated CPU time (s) 7.04
Current children cumulated vsize (KiB) 44396

Child status: 0
Real time (s): 8.96375
CPU time (s): 7.11644
CPU user time (s): 6.84443
CPU system time (s): 0.272017
CPU usage (%): 79.3914
Max. virtual memory (cumulated for all children) (KiB): 111004

getrusage(RUSAGE_CHILDREN,...) data:
user time used= 6.84443
system time used= 0.272017
maximum resident set size= 0
integral shared memory size= 0
integral unshared data size= 0
integral unshared stack size= 0
page reclaims= 44052
page faults= 273
swaps= 0
block input operations= 0
block output operations= 0
messages sent= 0
messages received= 0
signals received= 0
voluntary context switches= 385
involuntary context switches= 253

runsolver used 0 second user time and 0 second system time

The end