About Store Forum Documentation Contact



Post Reply 
LogN is verry slow (Windows)
Author Message
Aimless Offline
Member

Post: #1
LogN is verry slow (Windows)
Log and LogN is really slow (on my pc like ~100 LogN / second). Is it normal behaviour or is it just my PC?

my benchmark:
0 logs per frame: 9000 fps
1 logs per frame: 80 fps
10 logs per frame: 9 fps

test code:
PHP Code:
int total 0;

void InitPre()
{
   
EE_INIT();
   
D.mode(1024720);
}

bool Init()
{
   
//LogConsole();
   
D.sync(false);
   return 
true;
}
/******************************************************************************/
void Shut()
{
}
/******************************************************************************/
bool Update()
{
   if(
Kb.bp(KB_ESC))return false;

   for(
int i=0;  i<1;  ++iLogN(total++);
  
   return 
true;
}
/******************************************************************************/

void Draw()
{
   
D.clear(BLACK);
   
D.text(Vec2(00),  S+"Total: " total);
   
D.text(Vec2(0, -.1),  S+"fps: " Time.fps());
}
/**********************************w********************************************/ 
11-09-2017 12:39 PM
Find all posts by this user Quote this message in a reply
Zervox Offline
Member

Post: #2
RE: LogN is verry slow (Windows)
Sounds normal enough to me, LogN writes to file at the same time as it is called if I remember correctly.

you have to remember you shouldn't measure LogN performance with FPS as it is writing to disk which means it is stalling the CPU for the file to end write operation(meaning most of the time is spent on the drive access).
(This post was last modified: 11-09-2017 01:25 PM by Zervox.)
11-09-2017 01:22 PM
Find all posts by this user Quote this message in a reply
Aimless Offline
Member

Post: #3
RE: LogN is verry slow (Windows)
yeah fps isn't the best measurement for this kind of problem but anyways simple:
PHP Code:
FileText file("log.txt");
   
void log(const Strstr)
   {
         
file.putText(str);
         
file.putChar('\n');
         
file.flush();
   } 
can push like 100`000 lines/second. Why does LogN can't even thousand. Or am i missing something? I mean databases write stuff and flush reliably all the time and they can process thousands of queries per second.
(This post was last modified: 11-09-2017 01:51 PM by Aimless.)
11-09-2017 01:44 PM
Find all posts by this user Quote this message in a reply
Zervox Offline
Member

Post: #4
RE: LogN is verry slow (Windows)
if you want to log whatever you are looping to get detailed stats to a file I would probably do something like

Str s;

s+= information you want logged + '\n';
s+= more information you want logged + '\n';
s+= more information you want logged + '\n';
Logn(S+s);

EDIT:
answer to your question, it is because FileText is buffering it in memory before writing everything in one go to my knowledge.
EDIT2:
I wonder if LogN doesn't reopen the log file everytime the function is called then sets position to end then appends the file for every call, unlike filetext which you have to do it specficially, making it faster to write to.
(This post was last modified: 11-09-2017 01:58 PM by Zervox.)
11-09-2017 01:45 PM
Find all posts by this user Quote this message in a reply
Aimless Offline
Member

Post: #5
RE: LogN is verry slow (Windows)
Yes, it seems that LogN reopens the file each time it writes - mystery solved! Thanks smile
~1000x improvement. LogN anyways falls noticably behind direct file writing, but thats acceptable and probably because of OutputDebugString etc.

quick & dirty fix (wont work if LogFile string is changed, not sure if it is allowed):
Code:
--- a/Engine/Source/Misc/Misc.cpp                                    
+++ b/Engine/Source/Misc/Misc.cpp                                    
@@ -552,9 +552,13 @@ void Log    (C Str &text)                        
    #endif                                                            
                                                                      
       // write to file log                                          
-      if(Is(LogFile))                                                
-      {                                                              
-         FileText f; if(f.append(LogFile))                          
+         if (Is(LogFile))                                            
+         {                                                          
+                static FileText f;                                  
+                static bool is_open = false;                        
+                if (!is_open)                                        
+                       is_open = f.append(LogFile);                  
+                if (is_open)                                        
          {
(This post was last modified: 11-09-2017 02:38 PM by Aimless.)
11-09-2017 02:34 PM
Find all posts by this user Quote this message in a reply
Zervox Offline
Member

Post: #6
RE: LogN is verry slow (Windows)
if you are unsure you probably should put this in the source section of the forum, although I doubt EE would go head over heels for this as it isn't exposing anything vital of the engine. smile

Edit: Also the code you posted is for the Log function not LogN but the code change applies all the same I guess as LogN only adds '\n' unless I am mistaken smile
(This post was last modified: 11-09-2017 02:49 PM by Zervox.)
11-09-2017 02:45 PM
Find all posts by this user Quote this message in a reply
Aimless Offline
Member

Post: #7
RE: LogN is verry slow (Windows)
oh, ok didn't notice that forum section. But anyways, nothing top secret there smile
And yes LogN is implemented on top of Log so it applies to both.
11-09-2017 02:59 PM
Find all posts by this user Quote this message in a reply
Esenthel Online
Administrator

Post: #8
RE: LogN is verry slow (Windows)
Hi,
My tests, done in DEBUG mode:
0 logs per frame=300fps
1 logs per frame=200fps
2 logs per frame=160fps
10 logs per frame=60fps

I have an SSD, what about you?

Your modified "void Log (C Str &text)" does not call "f.flush" (internally called by file destructor) so you will not be able to see the results immediately, because they're buffered in RAM

If you want to do logging real-time, then I recommend dropping file/disk usage completely:
LogName(S); // disable disk usage
LogConsole(true); // open console for logging - Windows only
Also if you debug through Visual Studio, then you will see the output real-time in VS output window
So you will have VS output window + console output

Also: always avoid doing static variables inside function bodies, it costs performance - place them outside of the function.
11-09-2017 11:41 PM
Find all posts by this user Quote this message in a reply
Aimless Offline
Member

Post: #9
RE: LogN is verry slow (Windows)
No, my app was located on hard-drive which of course gives some slowdown. And yeah i forgot flush in the fixed version. Anyways I mean its not really serious issue, I just accidentally stumbled upon it and got confused grin I am going to write my own logging routines anyway as I will need to write different files later on.
Thanks.
(This post was last modified: 11-12-2017 05:54 PM by Aimless.)
11-12-2017 05:54 PM
Find all posts by this user Quote this message in a reply
Post Reply