Log in

View Full Version : (SOLVED) Machine Slowdown Query


StainlessS
7th August 2016, 20:12
SOLUTION:
Are you monitoring temperatures to check for thermal throttling?

Hi guys,
Getting some strange results where machine (Core Duo 2.4GHz, Duel Core, XP32SP3) slows over time doing exact same scans on YV12 ColorBars of duration 4 Hours.

Here Complete source to qCombed() v1.00 plugin:- (D9 thread http://forum.doom9.org/showthread.php?t=173754)

Only mods to published source are concerned with timing and DebugView output (mods marked in blue).


/*
qCombed() [ IsCombed() Mod by StainlessS @ Doom9.org.]

Mod of some of the source code in DeComb filter, FieldDeinterlace.cpp.
Original Decomb dll and source (c) Donald Graft, can be found here:- http://rationalqm.us/mine.html

*/

/*
qCombed() v1.0, 06 Aug 2016. First Release.

*/


#include <windows.h>
#include <stdio.h>
#include <time.h> // ssS Added for timings
#include "avisynth.h" // VERSION 3 header

// ssS Added
int __cdecl dprintf(char* fmt, ...) {
char printString[2048]="qCombed: ";
char *p=printString;
for(;*p++;);
--p; // @ null term
va_list argp;
va_start(argp, fmt);
vsprintf(p, fmt, argp);
va_end(argp);
for(;*p++;);
--p; // @ null term
if(printString == p || p[-1] != '\n') {
p[0]='\n'; // append n/l if not there already
p[1]='\0';
}
OutputDebugString(printString);
return p-printString; // strlen printString
}


AVSValue __cdecl GetVar(IScriptEnvironment* env, const char* name) {
try {return env->GetVar(name);} catch (IScriptEnvironment::NotFound) {} return AVSValue();
}




// Uses reference to dst else error (same dst for entire clip scan).
bool __cdecl qCombed_Planar(PVideoFrame src,PVideoFrame &dst,const int n,const int Th,int *counts,const int boxh,const int boxw) {
const BYTE *srcp = src->GetReadPtr(PLANAR_Y);
const int pitch = src->GetPitch(PLANAR_Y);
const w = src->GetRowSize(PLANAR_Y);
const h = src->GetHeight(PLANAR_Y);
// use box size of x=4 by y=8
const int boxarraysize = boxh * boxw;
const int CT = 4 * 8 / 2 - 1; // 15, (greater than this is at least half of max possible)
memset(counts, 0, sizeof(counts[0])*boxarraysize);
BYTE *dstp = dst->GetWritePtr(PLANAR_Y);
const int dpitch = dst->GetPitch(PLANAR_Y);
const dh = dst->GetHeight(PLANAR_Y);

const BYTE *above = srcp - pitch;
const BYTE *below = srcp + pitch;

memset(dstp,0,dh*dpitch); // dst is NewVideoFrame, ie not cropped.
int x, y;
for (y = 1; y < h - 1; ++y) {
srcp += pitch;
above += pitch;
below += pitch;
dstp += dpitch;
for (x = w; --x>=0;) {
const int val = ((long)above[x] - (long)srcp[x]) * ((long)below[x] - (long)srcp[x]);
if(val > Th) dstp[x] = 0xFF;
}
}
const BYTE *dp = dst->GetReadPtr(PLANAR_Y);
above = dp - dpitch;
below = dp + dpitch;
for (y = 1; y < h - 1; y++) {
const int boxy = (y >> 3) * boxw;
dp += dpitch;
above += dpitch;
below += dpitch;
for (x = w; --x>=0;) {
if (dp[x] == 0xFF && above[x] == 0xFF && below[x] == 0xFF) {
++counts[boxy + (x >> 2)];
}
}
}
bool ret=false;
for (x = boxarraysize; --x>=0;) {
if (counts[x] > CT) {ret = true; break;}
}
return ret;
}

AVSValue __cdecl qCombed(AVSValue args, void* user_data, IScriptEnvironment* env) {
char *myName="qCombed: ";
if(!args[0].IsClip()) env->ThrowError("%sMust have a clip",myName);
PClip child = args[0].AsClip();
const VideoInfo &vi=child->GetVideoInfo();
const bool yuy2 = vi.IsYUY2();
if(!vi.IsPlanar() && !yuy2) env->ThrowError("%sPlanar or YUY2 Only",myName);
if(vi.width==0||vi.num_frames<=0) env->ThrowError("%sClip has no video",myName);
int Th=args[1].AsInt(20);
if(Th<0 || Th>255) env->ThrowError("%sThreshold 0 -> 255",myName);
Th *= Th; // Squared
FILE *fp=NULL;
const fc=vi.num_frames;
int n=0;
const char *FileName = args[2].AsString("");
bool fpmd=(*FileName!='\0');
char ebf[256]=""; // No error so far
AVSValue ret;
if (!fpmd){ // Conditional filter function
if(args[6].IsInt()) {n = args[6].AsInt(); } // Frame n
else {
AVSValue cn = GetVar(env,"current_frame");
if (!cn.IsInt()) env->ThrowError("%s'current_frame' only available in runtime scripts",myName);
n = cn.AsInt(); // current_frame
}
n = (n<0) ? 0 : (n>=fc) ?fc-1:n; // Range limit frame n
}
if(ebf[0] == '\0') {
PVideoFrame src,dst;
src = child->GetFrame(n,env);
dst = env->NewVideoFrame(vi);
// use box size of x=4 by y=8
const boxh = (src->GetHeight(PLANAR_Y) + 8-1) / 8;
const boxw = (vi.width + 4-1) / 4; // vi.width, Planar or YUY2
int *counts= new int[boxh * boxw];
if (counts==NULL) strcpy(ebf,"counts memory alloc failure");
else if(!fpmd) {
ret = (yuy2) ? qCombed_YUY2(src,dst,n,Th,counts,boxh,boxw) : qCombed_Planar(src,dst,n,Th,counts,boxh,boxw);
} else {
int clipindex = args[3].AsInt(1); // ClipClop clip index 1 for combed frames
bool range= args[4].AsBool(false); // Single frames only
const char *rngsep_S = args[5].AsString("");
const int rngsep = (*rngsep_S<32 || *rngsep_S>126) ? ',' : *rngsep_S; // COMMA default
char FullPath[MAX_PATH];
if(_fullpath(FullPath,FileName, _MAX_PATH ) == NULL ) strcpy(ebf,"Cannot get full path.");
else {
if((fp=fopen(FullPath,"wt"))==NULL) strcpy(ebf,"Error opening dummy file for write");
else {
fclose(fp); // We will we be able to open file after scan
fp=NULL;
remove(FullPath); // kill dummy
char *cbf = new char[fc];
if(cbf==NULL) strcpy(ebf,"Cannot allocate comb buffer");
else {
memset(cbf,0,fc); // Prep for clip scan, clear combed flags
// ssS Modded to show timings
dprintf("Commencing combing scan");
double start_T = double(clock()) / double(CLOCKS_PER_SEC);
double sT = start_T;
int parts = min(20,fc);
int part=1;
int sf=0; // this time start frameno
int stopf = fc * part / parts;
double PercT=1.0; // anything
int cnt=0; // zero count of combed frames
for(n=0;n<fc;++n) {
src = child->GetFrame(n,env);
const bool q=(yuy2)
? qCombed_YUY2 (src,dst,n,Th,counts,boxh,boxw)
: qCombed_Planar(src,dst,n,Th,counts,boxh,boxw);
if(q) {
cbf[n]=1;
++cnt; // ++Combed count
}
if(n+1 >= stopf) {
double now = double(clock()) / double(CLOCKS_PER_SEC);
double Tim = max(now - sT,0.0001); // time taken for this part
double FPS = (n+1-sf)/Tim;
double SPF = 1.0/FPS;
if(sf==0) PercT=SPF; // 1st timing is 100.0%
double PartPerc=SPF * 100.0 / PercT; // Perc of 1st timing
dprintf("%d] %.2f%% nFrms=%d T=%.3fsec : %.2fFpS %.6fSpF Perc=%.2f%%",
n, (n+1)*100.0/fc ,n-sf+1,Tim,FPS,SPF,PartPerc);
sf=n+1; // next time start frame
sT=now; // next time start time
++part; // next time part number
stopf = fc * part / parts; // next time stop frame
}
}
ret = cnt; // Combed frames count for return
// Open text mode for Append
if((fp=fopen(FileName,"a+t"))==NULL) strcpy(ebf,"Cannot Open Frames file for write");
else {
double Tim = max(double(clock()) / double(CLOCKS_PER_SEC) - start_T,0.0001);
double FPS = fc/Tim;
double SPF = 1.0/FPS;
double AvePerc = SPF * 100.0 / PercT; // Perc of 1st timing
dprintf("Time=%.3fsecs (%.3fmins) : Avg %.3fFpS %.6fSpF Perc=%.2f%%",
Tim,Tim/60.0,FPS,SPF,AvePerc);
dprintf("Writing frames file");

char fbf[256];
if(!range) {
for(n=0;n<fc ;++n) {
if(cbf[n]!=0) {
if(clipindex<0) sprintf(fbf,"%d\n",n);
else sprintf(fbf,"%d %d\n",clipindex,n);
if(fwrite(fbf,strlen(fbf),1,fp)!=1) {
strcpy(ebf,"File write frame error");
break;
}
}
}
} else {
bool in=false;
int start = -1;
for(n=0; n<=fc ;++n) { // *** WARN ***, concludes at fc (FrameCount)
if(in && (n==fc || cbf[n]==0)) {
const int frms = n-start;
if(frms==1) {
if(clipindex<0) sprintf(fbf,"%d\n",start);
else sprintf(fbf,"%d %d\n",clipindex,start);
} else {
if(clipindex<0) sprintf(fbf,"%d%c%d\n",start,rngsep,n-1);
else sprintf(fbf,"%d %d%c%d\n",clipindex,start,rngsep,n-1);
}
if(fwrite(fbf,strlen(fbf),1,fp)!=1) {
strcpy(ebf,"File write range error");
break;
}
in = false;
start = -1;
} else if(!in && n<fc && cbf[n]!=0) {
start=n;
in=true;
}
}
}
}
delete [] cbf;
} // End of cbf==NULL
} // End of Open Dummy File
} // End of get FullPath
} // End of counts alloc
if(counts != NULL) {delete [] counts; counts=NULL;}
}
if(fp!=NULL) {fclose(fp); fp=NULL;}
if(ebf[0]!='\0') env->ThrowError("%s%s",myName,ebf);
return ret;
}


extern "C" __declspec(dllexport) const char* __stdcall AvisynthPluginInit2(IScriptEnvironment* env) {
env->AddFunction("qCombed" ,"c[Threshold]i[FileName]s[ClipIndex]i[Range]b[RngSep]s[n]i",qCombed , 0);
return "`qCombed' qCombed";
}


Question is, why is it slowing down over time ?
So far as I know, ColorBars keeps copy of same frame, so no cache problem there, and the called subroutine 'qCombed_Planar()' is doing exact same thing on each frame, and no memory allocs or anything being done within the concerned loop, the dst frame is from NewVideoFrame and re-used for entire scan (must provide to sub routine as reference otherwise problems if trying to take multiple write pointers on copy of writable video frame).

What is going on :confused:

Next post DebugView output

Here link to modded source and dll with timings code:- http://www.mediafire.com/download/vdpc647on11tabp/qCombed_v1.00_dll_Test.7z

Thanx in advance for your replies.

EDIT: Removed subroutine qCombed_YUY2 from source, too big for post (not of concern here).

EDIT: Small bug in above code (marked in red, fixed), frame counts off by 1 after 1st part(not a big problem).

sf=n+1; // next time start frame
sT=now; // next time start time
++part; // next time part number
stopf = fc * part / parts; // next time stop frame


EDIT: qCombed is a runtime function, not a filter (In File mode which we use here, will scan entire clip before return to script).
From docs

qCombed(), by StainlessS @ Doom9.org. http://forum.doom9.org/showthread.php?p=1776495#post1776495

Runtime function to establish combing status of video frames, or to write a frames file of combed frames [Intent for ClipClop() use].

ColorSpace, Planar and YUY2. (v2.5 dll but as only examines the luma channel can also function with v2.6 colorspaces).

qCombed() is a mod of IsCombed from DeComb plugin for Avisynth, (c) Donald Graft. [can be found here:- http://rationalqm.us/mine.html].


qCombed has two modes of operation, can use in conditional filter eg Scriptclip() or ConditionFilter() [just like IsCombed()],
and also has complete clip scan and frames file writing capability builtin.

StainlessS
7th August 2016, 20:16
DebugView.log


00000003 19:33:25.921 qCombed: Commencing combing scan
00000004 19:33:50.640 qCombed: 21577] 5.00% nFrms=21578 T=24.718sec : 872.97FpS 0.001146SpF Perc=100.00%
00000005 19:34:17.281 qCombed: 43155] 10.00% nFrms=21579 T=26.641sec : 809.99FpS 0.001235SpF Perc=107.77%
00000006 19:34:44.843 qCombed: 64734] 15.00% nFrms=21580 T=27.562sec : 782.96FpS 0.001277SpF Perc=111.50%
00000007 19:35:12.937 qCombed: 86312] 20.00% nFrms=21579 T=28.094sec : 768.10FpS 0.001302SpF Perc=113.65%
00000008 19:35:41.531 qCombed: 107891] 25.00% nFrms=21580 T=28.594sec : 754.70FpS 0.001325SpF Perc=115.67%
00000009 19:36:10.250 qCombed: 129469] 30.00% nFrms=21579 T=28.719sec : 751.38FpS 0.001331SpF Perc=116.18%
00000010 19:36:39.234 qCombed: 151047] 35.00% nFrms=21579 T=28.984sec : 744.51FpS 0.001343SpF Perc=117.25%
00000011 19:37:08.500 qCombed: 172626] 40.00% nFrms=21580 T=29.266sec : 737.37FpS 0.001356SpF Perc=118.39%
00000012 19:37:37.812 qCombed: 194204] 45.00% nFrms=21579 T=29.312sec : 736.18FpS 0.001358SpF Perc=118.58%
00000013 19:38:07.281 qCombed: 215783] 50.00% nFrms=21580 T=29.469sec : 732.29FpS 0.001366SpF Perc=119.21%
00000014 19:38:36.812 qCombed: 237361] 55.00% nFrms=21579 T=29.531sec : 730.72FpS 0.001369SpF Perc=119.47%
00000015 19:39:06.265 qCombed: 258939] 60.00% nFrms=21579 T=29.453sec : 732.66FpS 0.001365SpF Perc=119.15%
00000016 19:39:35.703 qCombed: 280518] 65.00% nFrms=21580 T=29.438sec : 733.07FpS 0.001364SpF Perc=119.08%
00000017 19:40:05.296 qCombed: 302096] 70.00% nFrms=21579 T=29.594sec : 729.17FpS 0.001371SpF Perc=119.72%
00000018 19:40:34.875 qCombed: 323675] 75.00% nFrms=21580 T=29.578sec : 729.60FpS 0.001371SpF Perc=119.65%
00000019 19:41:04.421 qCombed: 345253] 80.00% nFrms=21579 T=29.547sec : 730.33FpS 0.001369SpF Perc=119.53%
00000020 19:41:34.062 qCombed: 366831] 85.00% nFrms=21579 T=29.640sec : 728.04FpS 0.001374SpF Perc=119.91%
00000021 19:42:03.656 qCombed: 388410] 90.00% nFrms=21580 T=29.594sec : 729.20FpS 0.001371SpF Perc=119.72%
00000022 19:42:33.250 qCombed: 409988] 95.00% nFrms=21579 T=29.594sec : 729.17FpS 0.001371SpF Perc=119.72%
00000023 19:43:02.828 qCombed: 431567] 100.00% nFrms=21580 T=29.578sec : 729.60FpS 0.001371SpF Perc=119.65%
00000024 19:43:02.828 qCombed: Time=576.906secs (9.615mins) : Avg 748.073FpS 0.001337SpF Perc=116.70%
00000025 19:43:02.828 qCombed: Writing frames file
00000026 19:43:02.843 RT_DebugF: Combed Frame Count=0


Timing broken up into 5% parts, with frame number, % of clip done, number of frames in this part, time for this part, FPS for this part,
Seconds per frame for this part, and time taken Percentage based on seconds per frame of first 5% part (in blue above).

Test avs clip.

Colorbars(pixel_Type="YV12").Killaudio # 1 hour
Last ++ Last ++ Last ++ Last # 4 Hours
Z=qCombed(Filename="Test_Cmd.txt",Range=true) # Scan entire clip before return where frames file WOULD BE available IF COMBED
RT_DebugF("Combed Frame Count=%d",Z)
Return Last


The time taken Percentage based on seconds per frame of first part (last number) should probably be about same on any machine (assuming
they all exhibit slowdown).

Speed seems to stabilize after about 250,000 frames.
Memory steady, Pagefile steady at about 550MB, 50% CPU steady (ie 1 core).

EDIT: The qCombed() plug is irrelevant just code that repeatedly scans the frames and should take exact same time no matter
where in clip.

EDIT: Scan above was done with Anti-virus, firewall disabled, all background tasks and windows killed or closed, and after
hard drive defrag and registry defrag and clean boot.

EDIT: No throttling of any kind on machine.

EDIT: Oops, had a double posted thread somehow, deleted the copy.

kuchikirukia
9th August 2016, 16:14
Do you have a working script, because that doesn't.

StainlessS
9th August 2016, 18:46
Yeh it does. Requires linked qCombed and RT_Stats dll's (or just comment out the RT_DebugF line if no RT_).

EDIT: And obviously you need debugview to show/cap debug messages. https://technet.microsoft.com/en-us/sysinternals/debugview.aspx

kuchikirukia
9th August 2016, 20:10
It does nothing here.

Groucho2004
9th August 2016, 21:21
I used this script:
Colorbars(pixel_Type="YV12").Killaudio # 1 hour
Z=qCombed(Filename="Test_Cmd.txt",Range=true)
Return Last

Loading the script via "env->Invoke("Import", ...)" takes almost a minute, after that, the script (> 100,000 frames) runs through very quickly (less than a second). No idea what's happening there.

TheFluff
9th August 2016, 23:44
I used this script:
Colorbars(pixel_Type="YV12").Killaudio # 1 hour
Z=qCombed(Filename="Test_Cmd.txt",Range=true)
Return Last

Loading the script via "env->Invoke("Import", ...)" takes almost a minute, after that, the script (> 100,000 frames) runs through very quickly (less than a second). No idea what's happening there.

He's doing "compile-time processing" by requesting all frames in the entire clip in the filter constructor, that's why invoking the script takes so long and playing through it takes no time at all. I'm pretty sure both me and other people have told him repeatedly that this is a really stupid idea but he insists on doing it that way, instead of having something else request frames so the script actually works as expected.

I haven't really read the code but just to throw an idea out there, what about branch mispredictions (http://stackoverflow.com/questions/11227809/why-is-it-faster-to-process-a-sorted-array-than-an-unsorted-array) in the frame request loop? Then again the detection should give the same result on all frames since it's just colorbars. Might still be worth it to look at the disassembly though.

StainlessS
10th August 2016, 20:51
It does nothing here.

The debug output was the result, we were not expecting any combed frames to be found in ColorBars.

Here, qCombed_Planar()

// Uses reference to dst else error (same dst for entire clip scan).
bool __cdecl qCombed_Planar(PVideoFrame src,PVideoFrame &dst,const int n,const int Th,int *counts,const int boxh,const int boxw) {
const BYTE *srcp = src->GetReadPtr(PLANAR_Y);
const int pitch = src->GetPitch(PLANAR_Y);
const w = src->GetRowSize(PLANAR_Y);
const h = src->GetHeight(PLANAR_Y);
// use box size of x=4 by y=8
const int boxarraysize = boxh * boxw;
const int CT = 4 * 8 / 2 - 1; // 15, (greater than this is at least half of max possible)
memset(counts, 0, sizeof(counts[0])*boxarraysize);
BYTE *dstp = dst->GetWritePtr(PLANAR_Y);
const int dpitch = dst->GetPitch(PLANAR_Y);
const dh = dst->GetHeight(PLANAR_Y);

const BYTE *above = srcp - pitch;
const BYTE *below = srcp + pitch;

memset(dstp,0,dh*dpitch); // dst is NewVideoFrame, ie not cropped.
int x, y;
for (y = 1; y < h - 1; ++y) {
srcp += pitch;
above += pitch;
below += pitch;
dstp += dpitch;
for (x = w; --x>=0;) {
const int val = ((long)above[x] - (long)srcp[x]) * ((long)below[x] - (long)srcp[x]);
if(val > Th) dstp[x] = 0xFF;
}
}
const BYTE *dp = dst->GetReadPtr(PLANAR_Y);
above = dp - dpitch;
below = dp + dpitch;
for (y = 1; y < h - 1; y++) {
const int boxy = (y >> 3) * boxw;
dp += dpitch;
above += dpitch;
below += dpitch;
for (x = w; --x>=0;) {
if (dp[x] == 0xFF && above[x] == 0xFF && below[x] == 0xFF) {
++counts[boxy + (x >> 2)];
}
}
}
bool ret=false;
for (x = boxarraysize; --x>=0;) {
if (counts[x] > CT) {ret = true; break;}
}
return ret;
}

Assy

; 143 : for (x = w; --x>=0;) {

mov ebp, DWORD PTR _w$[esp+56]
add edi, esi
add edx, eax
add ebx, eax
dec ebp
mov DWORD PTR _dstp$[esp+56], edi
js SHORT $L75089

; 144 : const int val = ((long)above[x] - (long)srcp[x]) * ((long)below[x] - (long)srcp[x]);
; 145 : if(val > Th) dstp[x] = 0xFF;

mov edi, DWORD PTR _below$[esp+52]
mov esi, DWORD PTR _dstp$[esp+56]
mov ecx, ebx
sub ecx, edx
sub esi, edx
lea eax, DWORD PTR [edx+ebp]
sub edi, ebx
inc ebp
mov DWORD PTR tv722[esp+56], ecx
mov DWORD PTR tv729[esp+56], esi
mov DWORD PTR tv288[esp+56], ebp
jmp SHORT $L75092
$L76066:

; 139 : srcp += pitch;

mov ecx, DWORD PTR tv722[esp+56]
$L75092:

; 144 : const int val = ((long)above[x] - (long)srcp[x]) * ((long)below[x] - (long)srcp[x]);
; 145 : if(val > Th) dstp[x] = 0xFF;

movzx esi, BYTE PTR [eax]
add ecx, eax
movzx ebp, BYTE PTR [ecx+edi]
movzx ecx, BYTE PTR [ecx]
sub ecx, esi
sub ebp, esi
imul ebp, ecx
cmp ebp, DWORD PTR _Th$[esp+52]
jle SHORT $L75099
mov ecx, DWORD PTR tv729[esp+56]
mov BYTE PTR [ecx+eax], 255 ; 000000ffH
$L75099:
mov ecx, DWORD PTR tv288[esp+56]
dec eax
dec ecx
mov DWORD PTR tv288[esp+56], ecx
jne SHORT $L76066
mov eax, DWORD PTR _pitch$[esp+56]
mov esi, DWORD PTR _dpitch$[esp+56]
$L75089:
dec DWORD PTR tv326[esp+56]
jne SHORT $L75088

; 137 : int x, y;
; 138 : for (y = 1; y < h - 1; ++y) {

mov edi, DWORD PTR tv470[esp+56]
$L76067:

; 146 : }
; 147 : }
; 148 : const BYTE *dp = dst->GetReadPtr(PLANAR_Y);

mov edx, DWORD PTR _dst$[esp+52]
mov eax, DWORD PTR [edx]
mov ecx, DWORD PTR [eax+4]
mov eax, DWORD PTR [eax+8]
mov ecx, DWORD PTR [ecx]
lea ebp, DWORD PTR [eax+ecx]

; 149 : above = dp - dpitch;

mov edx, ebp

; 150 : below = dp + dpitch;
; 151 : for (y = 1; y < h - 1; y++) {

mov ebx, 1
sub edx, esi
cmp edi, ebx
lea eax, DWORD PTR [esi+ebp]
mov DWORD PTR _below$[esp+52], eax
mov DWORD PTR _y$[esp+52], ebx
jle $L75103
mov ecx, DWORD PTR _w$[esp+56]

; 165 : }
; 166 : return ret;

dec ecx
mov DWORD PTR tv475[esp+56], ecx
npad 6
$L76070:
mov eax, DWORD PTR _below$[esp+52]
add eax, esi
mov ecx, ebx
sar ecx, 3
imul ecx, DWORD PTR _boxw$[esp+52]
mov DWORD PTR _below$[esp+52], eax
mov eax, DWORD PTR tv475[esp+56]
add ebp, esi
add edx, esi
test eax, eax
mov DWORD PTR _dp$[esp+56], ebp
jl SHORT $L75102
mov edi, ebp
sub edi, edx
mov DWORD PTR tv781[esp+56], edi
mov edi, DWORD PTR _below$[esp+52]
sub edi, edx
lea ebx, DWORD PTR [eax+edx]
mov DWORD PTR tv717[esp+56], edi
npad 7
$L75106:
mov edi, DWORD PTR tv781[esp+56]
cmp BYTE PTR [edi+ebx], 255 ; 000000ffH
jne SHORT $L76068

; 152 : const int boxy = (y >> 3) * boxw;
; 153 : dp += dpitch;
; 154 : above += dpitch;
; 155 : below += dpitch;
; 156 : for (x = w; --x>=0;) {
; 157 : if (dp[x] == 0xFF && above[x] == 0xFF && below[x] == 0xFF) {

cmp BYTE PTR [ebx], 255 ; 000000ffH
jne SHORT $L76068
mov edi, DWORD PTR tv717[esp+56]
cmp BYTE PTR [ebx+edi], 255 ; 000000ffH
jne SHORT $L76068

; 158 : ++counts[boxy + (x >> 2)];

mov ebp, DWORD PTR _counts$[esp+52]
mov edi, eax
sar edi, 2
add edi, ecx
lea ebp, DWORD PTR [ebp+edi*4]
inc DWORD PTR [ebp]
mov ebp, DWORD PTR _dp$[esp+56]
$L76068:
dec eax
dec ebx
test eax, eax
jge SHORT $L75106
mov ebx, DWORD PTR _y$[esp+52]
mov edi, DWORD PTR tv470[esp+56]
$L75102:
inc ebx
cmp ebx, edi
mov DWORD PTR _y$[esp+52], ebx
jl $L76070
$L75103:

; 159 : }
; 160 : }
; 161 : }
; 162 : bool ret=false;
; 163 : for (x = boxarraysize; --x>=0;) {

mov eax, DWORD PTR _boxarraysize$[esp+56]
xor bl, bl
dec eax
js SHORT $L75112
mov ecx, DWORD PTR _counts$[esp+52]
$L75111:

; 164 : if (counts[x] > CT) {ret = true; break;}

cmp DWORD PTR [ecx+eax*4], 15 ; 0000000fH
jg SHORT $L76060

; 159 : }
; 160 : }
; 161 : }
; 162 : bool ret=false;
; 163 : for (x = boxarraysize; --x>=0;) {

dec eax
jns SHORT $L75111

; 164 : if (counts[x] > CT) {ret = true; break;}

jmp SHORT $L75112
$L76060:
mov bl, 1
$L75112:

; 165 : }
; 166 : return ret;

mov edi, DWORD PTR _src$[esp+52]
cmp DWORD PTR [edi], 1
mov esi, DWORD PTR __imp__InterlockedDecrement@4
jne SHORT $L76052
mov edx, DWORD PTR [edi+4]
add edx, 12 ; 0000000cH
push edx
call esi
$L76052:
push edi
call esi
pop edi
pop esi
pop ebp
mov al, bl
pop ebx

; 167 : }

add esp, 40 ; 00000028H
ret 0


:confused: EDIT: Above Assy produced by VS Toolkit 2003.

StainlessS
10th August 2016, 21:30
He's doing "compile-time processing" by requesting all frames in the entire clip in the filter constructor, that's why invoking the script takes so long and playing through it takes no time at all. I'm pretty sure both me and other people have told him repeatedly that this is a really stupid idea but he insists on doing it that way, instead of having something else request frames so the script actually works as expected.
...
Might still be worth it to look at the disassembly though.

Actually tis a function not a filter and has no constructor, it works exactly as I expected [EDIT: and documented] (except for the slow down).

As for really stupid,

This is standard clip scan script using IsCombed to write a frames file.

Avisource("D:\B40.avi") # Clip with combing
WriteFileIf("IsCombed.txt","IsCombed","current_frame")
Return Last

/*
AVSMeter 2.3.5 (x86) - Copyright (c) 2012-2016, Groucho2004
AviSynth 2.60 (ICL10) (2.6.0.6)

Number of frames: 10000
Length (hh:mm:ss.ms): 00:06:40.000
Frame width: 720
Frame height: 576
Framerate: 25.000 (25/1)
Colorspace: YV12

Frames processed: 10000 (0 - 9999)
FPS (min | max | average): 62.05 | 206.0 | 146.3
Memory usage (phys | virt): 105 | 113 MiB
Thread count: 3
CPU usage (average): 52%

Time (elapsed): 00:01:08.353
*/

10,000 frames, 68 seconds to process and then manually make another script to use the frames file. Note, IsCombed has MMX code.

Here, another script that uses TWriteAVI function "ForceProcessAVI" to force entire clip scan and produce file that can be used in 2nd pass, still using IsCombed function with MMX.


SHOW=True # ClipClop SHOW
SUBS=True # Show Time taken for IsCombed scan on frame
Index="1 " # ClipClop Index as string with following space separator
FN="IsCombedForced.txt" # Output filename
RT_FileDelete(FN) # Kill file.
#
Avisource("D:\B40.avi") # Clip with combing
AssumeTFF
ORG=Last
UNLACED=NNedi3(Field=-2, nns=2).SelectOdd # Some single rate deinterlacer
StartT=RT_TimerHP
WriteFileIf(FN,"IsCombed","Index","current_frame") # Write combed frames file with index for ClipClop.
ForceProcessAVI # Force Write file (From TWriteAVI v2.0)
Tim = RT_TimerHP - StartT
RT_DebugF("Tim=%.2fsecs",Tim)
ClipClop(Last,UNLACED,cmd=FN,Show=SHOW) # Replace DeInterlaced frames only.
(SUBS)?RT_Subtitle("IsCombed Scan Time=%.2fsecs",Tim,align=5):NOP
Return Last

# Show 65.34 secs

Marginally quicker at 65 seconds and as frames file is available can continue with 2nd pass and which we used in ClipClop.

Script using qCombed() without MMX and entire clip scan writing frames file (as frame ranges in ClipClop format with a clip index).

SHOW=True
SUBS=True # Show Time taken for IsCombed scan on frame
FN="Test_Cmd.txt"
#
Avisource("D:\B40.avi") # Clip with combing
AssumeTFF
StartT=RT_TimerHP
UNLACED=NNedi3(Field=-2, nns=2).SelectOdd
Z=qCombed(Filename=FN,Range=true)
Tim = RT_TimerHP - StartT
RT_DebugF("Combed Frame Count=%d Tim=%.2fsecs",Z,Tim)
ClipClop(Last,UNLACED,cmd=FN,Show=SHOW)
(SUBS)?RT_Subtitle("Combed Frame Count=%d Scan Time=%.2fsecs",Z,Tim,align=5):NOP
Return Last

/*
00000006 18:59:40.125 qCombed: Commencing combing scan
00000007 18:59:41.828 qCombed: 499] 5.00% nFrms=500 T=1.703sec : 293.60FpS 0.003406SpF Perc=100.00%
00000008 18:59:43.593 qCombed: 999] 10.00% nFrms=500 T=1.765sec : 283.29FpS 0.003530SpF Perc=103.64%
00000009 18:59:45.359 qCombed: 1499] 15.00% nFrms=500 T=1.766sec : 283.13FpS 0.003532SpF Perc=103.70%
00000010 18:59:47.062 qCombed: 1999] 20.00% nFrms=500 T=1.703sec : 293.60FpS 0.003406SpF Perc=100.00%
00000011 18:59:49.109 qCombed: 2499] 25.00% nFrms=500 T=2.047sec : 244.26FpS 0.004094SpF Perc=120.20%
00000012 18:59:51.093 qCombed: 2999] 30.00% nFrms=500 T=1.984sec : 252.02FpS 0.003968SpF Perc=116.50%
00000013 18:59:52.937 qCombed: 3499] 35.00% nFrms=500 T=1.844sec : 271.15FpS 0.003688SpF Perc=108.28%
00000014 18:59:54.812 qCombed: 3999] 40.00% nFrms=500 T=1.875sec : 266.67FpS 0.003750SpF Perc=110.10%
00000015 18:59:56.796 qCombed: 4499] 45.00% nFrms=500 T=1.984sec : 252.02FpS 0.003968SpF Perc=116.50%
00000016 18:59:58.703 qCombed: 4999] 50.00% nFrms=500 T=1.907sec : 262.19FpS 0.003814SpF Perc=111.98%
00000017 19:00:00.750 qCombed: 5499] 55.00% nFrms=500 T=2.047sec : 244.26FpS 0.004094SpF Perc=120.20%
00000018 19:00:02.718 qCombed: 5999] 60.00% nFrms=500 T=1.968sec : 254.07FpS 0.003936SpF Perc=115.56%
00000019 19:00:04.734 qCombed: 6499] 65.00% nFrms=500 T=2.016sec : 248.02FpS 0.004032SpF Perc=118.38%
00000020 19:00:06.734 qCombed: 6999] 70.00% nFrms=500 T=2.000sec : 250.00FpS 0.004000SpF Perc=117.44%
00000021 19:00:08.671 qCombed: 7499] 75.00% nFrms=500 T=1.937sec : 258.13FpS 0.003874SpF Perc=113.74%
00000022 19:00:10.640 qCombed: 7999] 80.00% nFrms=500 T=1.969sec : 253.94FpS 0.003938SpF Perc=115.62%
00000023 19:00:12.609 qCombed: 8499] 85.00% nFrms=500 T=1.969sec : 253.94FpS 0.003938SpF Perc=115.62%
00000024 19:00:14.609 qCombed: 8999] 90.00% nFrms=500 T=2.000sec : 250.00FpS 0.004000SpF Perc=117.44%
00000025 19:00:16.703 qCombed: 9499] 95.00% nFrms=500 T=2.094sec : 238.78FpS 0.004188SpF Perc=122.96%
00000026 19:00:18.687 qCombed: 9999] 100.00% nFrms=500 T=1.984sec : 252.02FpS 0.003968SpF Perc=116.50%
00000027 19:00:18.687 qCombed: Time=38.562secs (0.643mins) : Avg 259.323FpS 0.003856SpF Perc=113.22%
00000028 19:00:18.687 qCombed: Writing frames file
00000029 19:00:18.703 RT_DebugF: Combed Frame Count=2172
*/

38 seconds, and no messing around creating a 2nd pass script, can all be done in single script.

I would like to do it the really sensible way, but with 110 episodes of Babylon 5 to do, I just dont have that amount of free time.

EDIT: But thank you for all answers, much appreciated [EDIT: even the insulting ones :devil: ].

EDIT: Due to qCombed(), I can process Bab5 in two scripts per episode.
1), DGIndex auto created script to, De-comb, remove variable borders on all 4 sides that change from scene to scene, auto contrast setting
per scene, writing out to Lossless and convert to 44100KHz audio PCM via TWriteAVI v2.0 prior to second script.
2), Avisynthesizer_Mod template auto created script, MC Denoising and feed to MeGUI.

StainlessS
11th August 2016, 03:24
One of my rendering machines has just stopped after a couple of days working and I ran the test clip (P4 m/c, XP32).


00000006 3.56214857 [3624] qCombed: Commencing combing scan
00000007 40.36741257 [3624] qCombed: 21577] 5.00% nFrms=21578 T=36.812sec : 586.17FpS 0.001706SpF Perc=100.00%
00000008 76.99069214 [3624] qCombed: 43155] 10.00% nFrms=21578 T=36.625sec : 589.16FpS 0.001697SpF Perc=99.49%
00000009 113.55007935 [3624] qCombed: 64734] 15.00% nFrms=21579 T=36.547sec : 590.45FpS 0.001694SpF Perc=99.28%
00000010 150.11560059 [3624] qCombed: 86312] 20.00% nFrms=21578 T=36.578sec : 589.92FpS 0.001695SpF Perc=99.36%
00000011 186.78761292 [3624] qCombed: 107891] 25.00% nFrms=21579 T=36.672sec : 588.43FpS 0.001699SpF Perc=99.62%
00000012 223.36360168 [3624] qCombed: 129469] 30.00% nFrms=21578 T=36.578sec : 589.92FpS 0.001695SpF Perc=99.36%
00000013 259.92446899 [3624] qCombed: 151047] 35.00% nFrms=21578 T=36.563sec : 590.16FpS 0.001694SpF Perc=99.32%
00000014 296.49734497 [3624] qCombed: 172626] 40.00% nFrms=21579 T=36.562sec : 590.20FpS 0.001694SpF Perc=99.32%
00000015 332.97305298 [3624] qCombed: 194204] 45.00% nFrms=21578 T=36.484sec : 591.44FpS 0.001691SpF Perc=99.11%
00000016 369.53173828 [3624] qCombed: 215783] 50.00% nFrms=21579 T=36.563sec : 590.19FpS 0.001694SpF Perc=99.32%
00000017 406.05554199 [3624] qCombed: 237361] 55.00% nFrms=21578 T=36.516sec : 590.92FpS 0.001692SpF Perc=99.20%
00000018 442.57778931 [3624] qCombed: 258939] 60.00% nFrms=21578 T=36.531sec : 590.68FpS 0.001693SpF Perc=99.24%
00000019 479.17764282 [3624] qCombed: 280518] 65.00% nFrms=21579 T=36.594sec : 589.69FpS 0.001696SpF Perc=99.40%
00000020 515.75793457 [3624] qCombed: 302096] 70.00% nFrms=21578 T=36.578sec : 589.92FpS 0.001695SpF Perc=99.36%
00000021 552.36273193 [3624] qCombed: 323675] 75.00% nFrms=21579 T=36.609sec : 589.45FpS 0.001697SpF Perc=99.44%
00000022 588.90747070 [3624] qCombed: 345253] 80.00% nFrms=21578 T=36.547sec : 590.42FpS 0.001694SpF Perc=99.28%
00000023 625.47174072 [3624] qCombed: 366831] 85.00% nFrms=21578 T=36.562sec : 590.18FpS 0.001694SpF Perc=99.32%
00000024 662.16125488 [3624] qCombed: 388410] 90.00% nFrms=21579 T=36.688sec : 588.18FpS 0.001700SpF Perc=99.66%
00000025 698.72753906 [3624] qCombed: 409988] 95.00% nFrms=21578 T=36.578sec : 589.92FpS 0.001695SpF Perc=99.36%
00000026 735.34063721 [3624] qCombed: 431567] 100.00% nFrms=21579 T=36.609sec : 589.45FpS 0.001697SpF Perc=99.44%
00000027 735.34088135 [3624] qCombed: Time=731.796secs (12.197mins) : Avg 589.738FpS 0.001696SpF Perc=99.39%
00000028 735.34088135 [3624] qCombed: Writing frames file
00000029 735.34637451 [3624] RT_DebugF: Combed Frame Count=0


Ran it twice with almost identical results (no slowdown).
No idea what could be the cause, maybe some difference due to problem exhibiting machine being duel core ????

I'll run again on a second machine (again P4 XP32) in a day or so (when its finished working), but dont expect anything different to the first P4 result.

EDIT: In fact, ever so slight speed up, this probably due to my executing test via TightVNC, and then closing VNC as quick as I could,
so seems to speed up a teeny weeny bit.

TheFluff
11th August 2016, 03:32
I'm honestly confused as to why you think mentioning that your combing detection filter has MMX optimizations is relevant (what is this, 2001?), but disregarding that... the fundamental problem here is a principle of least astonishment (https://en.wikipedia.org/wiki/Principle_of_least_astonishment) violation.

So, Avisynth script is in some ways kind of a functional programming language. The fundamental principle and expectation is that it's the functions and their return values that are important. Still, while ugly, it's sometimes very useful to make functions in a language like this have side effects such as writing to a file. In Avisynth you might also have to deal with out-of-order frame requests, but still, people understand functions with side effects. What you're doing here is making the fucking compiler have potentially very significant and time-consuming side effects, and that is something that is deeply unsettling and offensive to me.

You know, there are several other people who have had similar problems and solutions to them. There are many analysis filters of various kinds that spit out their results to a file - scxvid, decomb, tivtc*, tdecimate and dedup all come to mind - and guess what they all have in common? Their side effects are tied to the frame request - the function call - and not to the script compilation. The only other filter I can think of that does something even remotely like this is ffms2 with its indexing, and that's due to unpleasant design restrictions - it's not a feature, and the software ships with a way to avoid it (ffmsindex.exe). By implementing it this way you're making your filter much harder to use for anyone who isn't really into your gimmick of doing absolutely everything with Avisynth script.

Other people solved the same problem by implementing standalone automation programs (see any Avisynth GUI thingie or toolkit programs like the YATTA Metrics Collector). You don't need to mess around with debugview shit if you can just print progress to stdout and look at it in a console window, you know. Interacting with an Avisynth script from a tiny little toy commandline utility in C++ is absolutely trivial (or you could just use some benchmarking utility), and if you've done that way you can just automate the entire thing with a simple batch file.


* speaking of which, any particular reason you're not doing combing detection with tivtc...?

StainlessS
11th August 2016, 03:51
I'm honestly confused as to why you think mentioning that your combing detection filter has MMX optimizations is relevant (what is this, 2001?), but disregarding that...

I certainly shall, as
Script using qCombed() without MMX and entire clip scan writing frames file
It does not have MMX.

something that is deeply unsettling and offensive to me.
Yeh, that comes across in almost all of your posts, no matter what the subject.

You really are an odd fish.

raffriff42
11th August 2016, 04:13
Have you tried using Performance Monitor (https://www.google.com/search?q=Performance+Monitor+slowdown&ie=utf-8&oe=utf-8) to track things like memory cache misses, page faults etc? Are you monitoring temperatures to check for thermal throttling?

StainlessS
11th August 2016, 04:30
Nope, but I shall, thanx Raff.

StainlessS
11th August 2016, 18:38
Raff, I tried System Performance Monitor as suggested but trying Core_Temp (XP +):- http://www.alcpu.com/CoreTemp/
Nailed it. Single Core hitting Tj.Max and accompanying momentary throttling of core by about 10% -> 15% (sometimes slightly more throttling,
did not seem to show drop in TaskManager).
I guess one thing that threw me was system fan goes hell-for-leather when encoding x264 (2 cores), but was spinning quite sedately during
qCombed scan, anyways,

Guess we can say solved here.

Thanks to RaffRiff42 and everybody who responded.

StainlessS
12th August 2016, 16:02
Original timing, Hitting Tj.Max (Hitting 85C, max rated by manufacturer)

00000003 19:33:25.921 qCombed: Commencing combing scan
00000004 19:33:50.640 qCombed: 21577] 5.00% nFrms=21578 T=24.718sec : 872.97FpS 0.001146SpF Perc=100.00%
00000005 19:34:17.281 qCombed: 43155] 10.00% nFrms=21579 T=26.641sec : 809.99FpS 0.001235SpF Perc=107.77%
00000006 19:34:44.843 qCombed: 64734] 15.00% nFrms=21580 T=27.562sec : 782.96FpS 0.001277SpF Perc=111.50%
00000007 19:35:12.937 qCombed: 86312] 20.00% nFrms=21579 T=28.094sec : 768.10FpS 0.001302SpF Perc=113.65%
00000008 19:35:41.531 qCombed: 107891] 25.00% nFrms=21580 T=28.594sec : 754.70FpS 0.001325SpF Perc=115.67%
00000009 19:36:10.250 qCombed: 129469] 30.00% nFrms=21579 T=28.719sec : 751.38FpS 0.001331SpF Perc=116.18%
00000010 19:36:39.234 qCombed: 151047] 35.00% nFrms=21579 T=28.984sec : 744.51FpS 0.001343SpF Perc=117.25%
00000011 19:37:08.500 qCombed: 172626] 40.00% nFrms=21580 T=29.266sec : 737.37FpS 0.001356SpF Perc=118.39%
00000012 19:37:37.812 qCombed: 194204] 45.00% nFrms=21579 T=29.312sec : 736.18FpS 0.001358SpF Perc=118.58%
00000013 19:38:07.281 qCombed: 215783] 50.00% nFrms=21580 T=29.469sec : 732.29FpS 0.001366SpF Perc=119.21%
00000014 19:38:36.812 qCombed: 237361] 55.00% nFrms=21579 T=29.531sec : 730.72FpS 0.001369SpF Perc=119.47%
00000015 19:39:06.265 qCombed: 258939] 60.00% nFrms=21579 T=29.453sec : 732.66FpS 0.001365SpF Perc=119.15%
00000016 19:39:35.703 qCombed: 280518] 65.00% nFrms=21580 T=29.438sec : 733.07FpS 0.001364SpF Perc=119.08%
00000017 19:40:05.296 qCombed: 302096] 70.00% nFrms=21579 T=29.594sec : 729.17FpS 0.001371SpF Perc=119.72%
00000018 19:40:34.875 qCombed: 323675] 75.00% nFrms=21580 T=29.578sec : 729.60FpS 0.001371SpF Perc=119.65%
00000019 19:41:04.421 qCombed: 345253] 80.00% nFrms=21579 T=29.547sec : 730.33FpS 0.001369SpF Perc=119.53%
00000020 19:41:34.062 qCombed: 366831] 85.00% nFrms=21579 T=29.640sec : 728.04FpS 0.001374SpF Perc=119.91%
00000021 19:42:03.656 qCombed: 388410] 90.00% nFrms=21580 T=29.594sec : 729.20FpS 0.001371SpF Perc=119.72%
00000022 19:42:33.250 qCombed: 409988] 95.00% nFrms=21579 T=29.594sec : 729.17FpS 0.001371SpF Perc=119.72%
00000023 19:43:02.828 qCombed: 431567] 100.00% nFrms=21580 T=29.578sec : 729.60FpS 0.001371SpF Perc=119.65%
00000024 19:43:02.828 qCombed: Time=576.906secs (9.615mins) : Avg 748.073FpS 0.001337SpF Perc=116.70%
00000025 19:43:02.828 qCombed: Writing frames file
00000026 19:43:02.843 RT_DebugF: Combed Frame Count=0


Akasa X4 Heatsink/Fan (had new boxed one lying around), Good dollop thermal paste, good dust down and clean out. (Max 48C over entire run).

00000006 15:42:11.609 qCombed: Commencing combing scan
00000007 15:42:35.312 qCombed: 21577] 5.00% nFrms=21578 T=23.703sec : 910.35FpS 0.001098SpF Perc=100.00%
00000008 15:42:58.984 qCombed: 43155] 10.00% nFrms=21578 T=23.672sec : 911.54FpS 0.001097SpF Perc=99.87%
00000009 15:43:22.656 qCombed: 64734] 15.00% nFrms=21579 T=23.672sec : 911.58FpS 0.001097SpF Perc=99.86%
00000010 15:43:46.312 qCombed: 86312] 20.00% nFrms=21578 T=23.656sec : 912.16FpS 0.001096SpF Perc=99.80%
00000011 15:44:09.953 qCombed: 107891] 25.00% nFrms=21579 T=23.641sec : 912.78FpS 0.001096SpF Perc=99.73%
00000012 15:44:33.593 qCombed: 129469] 30.00% nFrms=21578 T=23.641sec : 912.74FpS 0.001096SpF Perc=99.74%
00000013 15:44:57.265 qCombed: 151047] 35.00% nFrms=21578 T=23.671sec : 911.58FpS 0.001097SpF Perc=99.86%
00000014 15:45:20.890 qCombed: 172626] 40.00% nFrms=21579 T=23.625sec : 913.40FpS 0.001095SpF Perc=99.67%
00000015 15:45:44.531 qCombed: 194204] 45.00% nFrms=21578 T=23.641sec : 912.74FpS 0.001096SpF Perc=99.74%
00000016 15:46:08.203 qCombed: 215783] 50.00% nFrms=21579 T=23.672sec : 911.58FpS 0.001097SpF Perc=99.86%
00000017 15:46:31.828 qCombed: 237361] 55.00% nFrms=21578 T=23.625sec : 913.35FpS 0.001095SpF Perc=99.67%
00000018 15:46:55.500 qCombed: 258939] 60.00% nFrms=21578 T=23.672sec : 911.54FpS 0.001097SpF Perc=99.87%
00000019 15:47:19.140 qCombed: 280518] 65.00% nFrms=21579 T=23.640sec : 912.82FpS 0.001096SpF Perc=99.73%
00000020 15:47:42.781 qCombed: 302096] 70.00% nFrms=21578 T=23.641sec : 912.74FpS 0.001096SpF Perc=99.74%
00000021 15:48:06.453 qCombed: 323675] 75.00% nFrms=21579 T=23.672sec : 911.58FpS 0.001097SpF Perc=99.86%
00000022 15:48:30.093 qCombed: 345253] 80.00% nFrms=21578 T=23.641sec : 912.74FpS 0.001096SpF Perc=99.74%
00000023 15:48:53.718 qCombed: 366831] 85.00% nFrms=21578 T=23.625sec : 913.35FpS 0.001095SpF Perc=99.67%
00000024 15:49:17.390 qCombed: 388410] 90.00% nFrms=21579 T=23.671sec : 911.62FpS 0.001097SpF Perc=99.86%
00000025 15:49:41.046 qCombed: 409988] 95.00% nFrms=21578 T=23.657sec : 912.12FpS 0.001096SpF Perc=99.81%
00000026 15:50:04.703 qCombed: 431567] 100.00% nFrms=21579 T=23.656sec : 912.20FpS 0.001096SpF Perc=99.80%
00000027 15:50:04.703 qCombed: Time=473.094secs (7.885mins) : Avg 912.225FpS 0.001096SpF Perc=99.79%
00000028 15:50:04.703 qCombed: Writing frames file
00000029 15:50:04.718 RT_DebugF: Combed Frame Count=0


running coooooler, and faster, less noise. Lovely http://www.cosgan.de/images/smilie/froehlich/e035.gif

EDIT: As new fan sucks in air from near RAM, might also be keeping that a tad cooler.

EDIT: Full load, never goes above about 55C.