Recent

Author Topic: WriteLN Compiler Differences 2.4 vs 2.6  (Read 8690 times)

alfware17

  • New Member
  • *
  • Posts: 29
WriteLN Compiler Differences 2.4 vs 2.6
« on: January 29, 2016, 12:02:15 am »
Hallo, I have a console program, sorting files with nearly unlimited buffer files - old stuff but it works fine.

So every time I update Lazarus/FreePascal, I recompile it und try my benchmarks, how long does it take to sort 10 Mio lines and so on.
Now I found out the terrible fact >:D my program has become slower :-*  I searched for the reason and found out, it happens to my final
output routine, when I WriteLN all the stuff. But only in that mode, when I use stdout (and then redirect in Windows, here Vista).
When I write into file with name (the other mode), all is fine.

I found the program to become significant slower (by 25%) when compiled with FPC 2.6.2 instead the older 2.4.4.  Newer (3.0.0)
and older (2.4.2 and 2.2.4) is the same - the boarder is at version 2.4.

You now may say - don't recompile it. Use the file writeln mode only.... I just wanted to understand why, and may be there is some  solution
to fix it. Some must not assume, programs may become slower - but the reason could be easy: a compiler switch, any changed structure in the compiler itself or simply my stupidness.
Anybody can help me? Thank you a lot

Leledumbo

  • Hero Member
  • *****
  • Posts: 8112
  • Programming + Glam Metal + Tae Kwon Do = Me
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #1 on: January 29, 2016, 05:19:37 am »
Feel free to examine the svn log. Newer FPC gives faster code in general for me, but 3.0.0 has string "improvement" that may slow down string processing a bit, so it really depends on what and how you code. Show output from any profiler you know to prove that the bottleneck is really the writeln, blind guess won't help.

Thaddy

  • Hero Member
  • *****
  • Posts: 9190
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #2 on: January 29, 2016, 09:06:28 am »
Well, string console output didn't change that much, so I expect a setting is different.

What is more likely is that the older version always defaults to shortstrings and newer ones depending on modes like Delphi and ObjFpc  may be  compiled with long strings.({$H+})

I suspect that when you recompile your code with {$H-} or from the commandline I believe with  -Sh- you will get your performance back.

Especially for console mode apps: if you can use shortstrings, use them! Much faster.
If you STILL have a performance difference, plz report back. There shouldn't be that much in it.
also related to equus asinus.

alfware17

  • New Member
  • *
  • Posts: 29
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #3 on: January 29, 2016, 04:28:10 pm »
Hallo

@ Leledumbo: Unfortunately I am a dummy and don't know much about SVN. Exactly only the name...
 
But now I have source code for you and some prepared test.
First of all: hope I haven't deleted to much (see attachment) to fit the 250kb Boarder.
If so, please look for the whole ZIP at
-- DELETED --

It's my project and I added some batches to make my problem clear.
It's no blind guessing :-* it was really hard job for my PC and it's a pity that it is so repeatable...

To get an input file, run TEST13.BAT - it create the ERGLOG13.TXT as it should be in my BENCH20 project.

After that you only need the 244.BAT, 262.BAT, 300.BAT and so on - using the version of my QSORT program
compiled with different versions of the FPC compiler.
You can run it - but you don't need - I have already created the outputs: ERGLOG13-alle244.TXT oder ERGLOG13-alle262.TXT
and so on.

The problem now is: With compiler 2.6.2 and up the "slow" version (written to stdout and redirected) ist significant slower
than the "fast" version (output to assigned file).   With the 2.4.4 compiler and older there was no such difference. :P

In the "slow" version I cannot write comments for the progress (because the stdout is redirected and used), but I watched
in real time with my Total Commander ;D that the problem is in fact at the last matching of files and finally writing by writeln
to stdout.  It lasts for about 30 s (at my hardware) where the "fast" only needs 10.

It referes to the line codes 580/581 and 1041/1042 (ruled by the ausok variable).  There is nearly no influence of my algorithm
(dynamic buffers or B-Tree which result in the number of files to match last - here for TEST13 five for the dynamic case and 2 for the B-Tree).

@ Thaddy
Also "ShortString" is not the problem - I found out, my compiler uses it as default but I written explicite. I even made the test with long String,
the result was: all versions run up to 150% longer  >:( but the difference between "slow" and "fast" remained equal. It must have another
reason. 

I do believe in any switch too - but how to find out? It would help me to see, which switches the FPC (commandline but I can use IDE as well)
uses actually?! Does it show me anywhere?. 

Thank You for any good idea
« Last Edit: March 10, 2016, 11:03:30 pm by alfware17 »

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 5713
    • wiki
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #4 on: January 29, 2016, 04:42:19 pm »
At least on Windows....

If it is indeed the writeln to stdout that now takes longer, then I would *GUESS* that it could be the encoding of strings.
More so, the encoding expected by the API of the OS.
Afaik Win has an Api for 8bit legacy ansi that depends on the users codepage/localization; and it has a 16 bit widestring unicode API.
I am not sure, but it may be that fpc changed to the later. Then all your strings would have to be re-encoded.

Just an idea, not sure if any of this applies.

Thaddy

  • Hero Member
  • *****
  • Posts: 9190
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #5 on: January 29, 2016, 05:06:39 pm »
Shortstring doesn't have any fancy encoding afaik.

But just to determine all things being equal since MS did a lot of work on the console as well in windows 10: Do you use different platforms to test different compilers, i.e. does the old code run an old windows and the new code on Windows 10? In that case, put the console in "legacy mode". That is a console setting  and can be accessed through  a started console | left click  top-left corner|properties|options.
also related to equus asinus.

Martin_fr

  • Administrator
  • Hero Member
  • *
  • Posts: 5713
    • wiki
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #6 on: January 29, 2016, 05:13:41 pm »
Shortstring doesn't have any fancy encoding afaik.
Yes but it is 8bit.
*IF* fpc changed to using the windows 16bit API....

I do not know.
But you can compile to asm, and check
« Last Edit: January 29, 2016, 05:15:53 pm by Martin_fr »

marcov

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 7508
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #7 on: January 29, 2016, 06:31:06 pm »
Do you use settextbuf ?

For the to file case?

Leledumbo

  • Hero Member
  • *****
  • Posts: 8112
  • Programming + Glam Metal + Tae Kwon Do = Me
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #8 on: January 29, 2016, 11:52:08 pm »
I don't have windows so I use wine + timeit from windows 2003 resource kit to test (cannot use bash time because wine has startup overhead). To make sure the result is consistent, each .bat is run 10 times.
Code: Bash  [Select]
  1. $ for i in {1..10}; do WINEDEBUG=fixme-all wine timeit -t 244.bat > /dev/null; done
  2. Elapsed Time:     0:00:03.797
  3. Elapsed Time:     0:00:03.806
  4. Elapsed Time:     0:00:03.797
  5. Elapsed Time:     0:00:03.762
  6. Elapsed Time:     0:00:03.832
  7. Elapsed Time:     0:00:03.799
  8. Elapsed Time:     0:00:03.775
  9. Elapsed Time:     0:00:03.764
  10. Elapsed Time:     0:00:03.812
  11. Elapsed Time:     0:00:03.847
  12. $ for i in {1..10}; do WINEDEBUG=fixme-all wine timeit -t 262.bat > /dev/null; done
  13. Elapsed Time:     0:00:03.943
  14. Elapsed Time:     0:00:03.766
  15. Elapsed Time:     0:00:03.714
  16. Elapsed Time:     0:00:03.751
  17. Elapsed Time:     0:00:03.798
  18. Elapsed Time:     0:00:03.766
  19. Elapsed Time:     0:00:03.805
  20. Elapsed Time:     0:00:03.831
  21. Elapsed Time:     0:00:03.775
  22. Elapsed Time:     0:00:03.779
  23. $ for i in {1..10}; do WINEDEBUG=fixme-all wine timeit -t 264.bat > /dev/null; done
  24. Elapsed Time:     0:00:03.906
  25. Elapsed Time:     0:00:03.906
  26. Elapsed Time:     0:00:03.923
  27. Elapsed Time:     0:00:03.830
  28. Elapsed Time:     0:00:03.898
  29. Elapsed Time:     0:00:03.918
  30. Elapsed Time:     0:00:03.967
  31. Elapsed Time:     0:00:03.966
  32. Elapsed Time:     0:00:04.008
  33. Elapsed Time:     0:00:03.853
  34. $ for i in {1..10}; do WINEDEBUG=fixme-all wine timeit -t 300.bat > /dev/null; done
  35. Elapsed Time:     0:00:03.769
  36. Elapsed Time:     0:00:03.919
  37. Elapsed Time:     0:00:03.851
  38. Elapsed Time:     0:00:03.841
  39. Elapsed Time:     0:00:03.878
  40. Elapsed Time:     0:00:03.850
  41. Elapsed Time:     0:00:03.916
  42. Elapsed Time:     0:00:03.974
  43. Elapsed Time:     0:00:03.855
  44. Elapsed Time:     0:00:03.833
  45.  
As you can see, there's no significant difference here (less than 2 seconds difference on a multitasking OS doesn't count, even when no user programs running). It must be something else on your system.

alfware17

  • New Member
  • *
  • Posts: 29
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #9 on: January 30, 2016, 12:03:45 pm »
@ Leledumbo:
    Wow - less than 4 seconds?! And (Wine) simulated? Do you have a super computer?
    At mine it takes 1:00 min for 1 call in the fast case (writeln to file)
    but 1:20 min in the mysterious slow case (writeln to stdout and redirect).
    And in the 244.bat there are 4 calls, each for 5.000.000 lines to sort.

    It sounds to me like you didn't call TEST13 only once before,
    so there was not created the input file (about 300 MB :-).
    Then all 4 calls have only flushed...

@ Markov: Yes I did - settextbuf for each input/output file (up to 15), for the named input, named output, for stdin and stdout, each 8k.
   After your suggestion I increased the textbuf for the stdout to 64k - no measurable time effect - the 20s difference remained.
   In any forum I read about the problem could be stdout is flushed after each write - but why then does the 2.4.4 compiler better?

@ Martin_fr: I try to guess, what you wanted to tell me, but I don't understand. FPC made or let any codepage adaptions? My computer told
   me CONSOLE is in codepage 850 and the default system is 1252.   All my German ÄÖÜ߀ work fine :-*
   But what does it mean to me, if a recoding is the bottleneck. What should I do?

Thaddy

  • Hero Member
  • *****
  • Posts: 9190
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #10 on: January 30, 2016, 12:34:12 pm »
Shortstring doesn't have any fancy encoding afaik.
Yes but it is 8bit.
*IF* fpc changed to using the windows 16bit API....

I do not know.
But you can compile to asm, and check

I do know and that would make even less sense since the char routines for 8 bit are almost all of them since XP/2000 actually OS level proxies to OS 16 bit unicode calls.
« Last Edit: January 30, 2016, 01:01:25 pm by Thaddy »
also related to equus asinus.

engkin

  • Hero Member
  • *****
  • Posts: 2513
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #11 on: January 30, 2016, 03:58:36 pm »
The problem now is: With compiler 2.6.2 and up the "slow" version (written to stdout and redirected) ist significant slower
than the "fast" version (output to assigned file).   With the 2.4.4 compiler and older there was no such difference. :P

Could you typecast the strings into pchar in your WriteLn. Instead of:
Code: Pascal  [Select]
  1. WriteLN(MERGE(buffer))
  2. ...and
  3. WriteLN(BLATT_MERGE)

use
Code: Pascal  [Select]
  1. WriteLN(pchar(MERGE(buffer)))
  2. ...and
  3. WriteLN(pchar(BLATT_MERGE))

and run your tests again.


You seem to be sure that the problem is related to WriteLn where you point to your code at:
Code: Pascal  [Select]
  1.          IF ausok
  2.             THEN WriteLN(ausdatei,MERGE(buffer))
  3.             ELSE WriteLN(MERGE(buffer));

and

Code: Pascal  [Select]
  1.             IF ausok
  2.                THEN WriteLN(ausdatei,BLATT_MERGE)
  3.                ELSE WriteLN(BLATT_MERGE);

all of these WriteLn calls would result in calls to fpc_Write_Text_AnsiStr

in FPC 2.4.2:
Code: Pascal  [Select]
  1. Procedure fpc_Write_Text_AnsiStr (Len : Longint; Var f : Text; const S : AnsiString); iocheck; [Public,alias:'FPC_WRITE_TEXT_ANSISTR']; compilerproc;
  2. {
  3.  Writes a AnsiString to the Text file T
  4. }
  5. var
  6.   SLen : longint;
  7. begin
  8.   If (InOutRes<>0) then
  9.    exit;
  10.   case TextRec(f).mode of
  11.     fmOutput { fmAppend gets changed to fmOutPut in do_open (JM) }:
  12.       begin
  13.         SLen:=Length(s);
  14.         If Len>SLen Then
  15.           fpc_WriteBlanks(f,Len-SLen);
  16.         if slen > 0 then
  17.           fpc_WriteBuffer(f,PChar(S)^,SLen);
  18.       end;
  19.     fmInput: InOutRes:=105
  20.     else InOutRes:=103;
  21.   end;
  22. end;
  23.  

in FPC 3.0.0:
Code: Pascal  [Select]
  1. Procedure fpc_Write_Text_AnsiStr (Len : Longint; Var f : Text; const S : RawByteString); iocheck; [Public,alias:'FPC_WRITE_TEXT_ANSISTR']; compilerproc;
  2. {
  3.  Writes a AnsiString to the Text file T
  4. }
  5. var
  6.   SLen: longint;
  7.   a: RawByteString;
  8. begin
  9.   If (InOutRes<>0) then
  10.    exit;
  11.   case TextRec(f).mode of
  12.     fmOutput { fmAppend gets changed to fmOutPut in do_open (JM) }:
  13.       begin
  14.         SLen:=Length(s);
  15.         If Len>SLen Then
  16.           fpc_WriteBlanks(f,Len-SLen);
  17.         if SLen > 0 then
  18.           begin
  19.             {$if defined(FPC_HAS_CPSTRING) and defined(FPC_HAS_FEATURE_ANSISTRINGS)}
  20.             if TextRec(f).CodePage<>TranslatePlaceholderCP(StringCodePage(S)) then
  21.               begin
  22.                 a:=fpc_AnsiStr_To_AnsiStr(S,TextRec(f).CodePage);
  23.                 fpc_WriteBuffer(f,PAnsiChar(a)^,Length(a));
  24.               end
  25.             else
  26.             {$endif}
  27.             fpc_WriteBuffer(f,PAnsiChar(s)^,SLen);
  28.           end;
  29.       end;
  30.     fmInput: InOutRes:=105
  31.     else InOutRes:=103;
  32.   end;
  33. end;
  34.  

As you can see, a new condition:
Code: Pascal  [Select]
  1.             if TextRec(f).CodePage<>TranslatePlaceholderCP(StringCodePage(S)) then
which results in two calls to TranslatePlaceholderCP and StringCodePage

This condition, if true then:
Code: Pascal  [Select]
  1.               begin
  2.                 a:=fpc_AnsiStr_To_AnsiStr(S,TextRec(f).CodePage);
a third call to fpc_AnsiStr_To_AnsiStr

Bart

  • Hero Member
  • *****
  • Posts: 3541
    • Bart en Mariska's Webstek
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #12 on: January 30, 2016, 04:04:06 pm »
@Engkin: TS is comparing 2.6.2 and 2.4.4 compiler.
Neither of them support cp aware strings.

Bart

marcov

  • Global Moderator
  • Hero Member
  • *****
  • Posts: 7508
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #13 on: January 30, 2016, 04:05:02 pm »
To test if flushing is the culprit you could try

Code: Pascal  [Select]
  1. textrec(output).FlushFunc:=nil;

It could be that the redirection detection fails for some reason.

(from rtl/inc/text.inc:

Code: Pascal  [Select]
  1.  begin
  2.      t.InOutFunc:=@FileWriteFunc;
  3.      { Only install flushing if its a NOT a file, and only check if there
  4.        was no error opening the file, because else we always get a bad
  5.        file handle error 6 (PFV) }
  6.      if (InOutRes=0) and
  7.         Do_Isdevice(t.Handle) then
  8.       t.FlushFunc:=@FileWriteFunc;
  9.    end;
  10.  

do_isdevice is IOCTL_TCGETS on Linux. Should be visible when stracing.
« Last Edit: January 30, 2016, 04:07:10 pm by marcov »

Thaddy

  • Hero Member
  • *****
  • Posts: 9190
Re: WriteLN Compiler Differences 2.4 vs 2.6
« Reply #14 on: January 30, 2016, 04:59:59 pm »
As you can see, a new condition:

Yes, but no. TS already stated he's using shortstrings.
also related to equus asinus.