[M3devel] performance problems in CM3 Text operations on AMD64_LINUX

[Rodney M. Bates]

On 01/04/2014 12:55 PM, mika at async.caltech.edu wrote:
> I have this program that generates Modula-3 code from XML.
>
> It uses Wr.PutText a lot, on small strings.
>
> It runs 10 times faster under PM3 on FreeBSD/i386 on a 2 GHz old Pentium
> III type computer than under CM3 (at head) on Debian/amd64 on a 4 GHz
> Core i7 4960X.
>
> (176)rover:~/t/calarm/fix/gen/src>time ../FreeBSD4/genfix -o ../../fix42/src -T ../templates -L fix42 FIX42.xml
> 0.419u 0.089s 0:00.70 70.0%     471+27608k 0+546io 0pf+0w
>
> (29)truffles:~/t/calarm/fix/gen/src>time ../AMD64_LINUX/genfix -o ../../fix42/src -T ../templates -L fix42 FIX42.xml
> 1.952u 0.232s 0:05.40 40.3%     0+0k 0+11504io 0pf+0w
>
> I believe the issue is that Text.m3 is making a ton of system calls!
>
> Here's a typical traceback:
>
> (gdb) where
> #0  0x00002aaaaaacb770 in ?? ()
> #1  0x00002aaaaaacba1b in gettimeofday ()
> #2  0x00002aaaac468f8a in gettimeofday () at ../sysdeps/unix/sysv/linux/x86_64/gettimeofday.S:37
> #3  0x000000000048c10c in TimePosix__Now () at ../src/time/POSIX/TimePosixC.c:50
> #4  0x000000000048b4d2 in Time__Now () at ../src/time/POSIX/TimePosix.m3:14
> #5  0x000000000049cbcf in TextStats__NoteFinished (M3_ESffkp_o=<error reading variable>) at ../src/text/TextStats.m3:64
> #6  0x00000000004921de in Text__SetChars (M3_CKMnXU_a=<error reading variable>, M3_Bd56fi_t=<error reading variable>,
>      M3_Cwb5VA_start=<error reading variable>) at ../src/text/Text.m3:512
> #7  0x0000000000441a26 in UnsafeWr__FastPutText (M3_BxxOH1_wr=<error reading variable>, M3_Bd56fi_t=<error reading variable>) at ../src/rw/Wr.m3:100
> #8  0x000000000044192f in Wr__PutText (M3_BxxOH1_wr=<error reading variable>, M3_Bd56fi_t=<error reading variable>) at ../src/rw/Wr.m3:89
> #9  0x000000000041627f in M3Syntax__TextSetPutList (M3_CT76zs_s=<error reading variable>, M3_BxxOH1_wr=<error reading variable>,
>      M3_AicXUJ_quoted=<error reading variable>) at ../src/M3Syntax.m3:129
> #10 0x00000000004169cf in M3Syntax__EnumToText (M3_Bqnwti_e=<error reading variable>, M3_ACGgGY_env=<error reading variable>) at ../src/M3Syntax.m3:173
> #11 0x000000000041791a in M3Syntax__UnstrToText (M3_AIPC2K_u=<error reading variable>, M3_ACGgGY_env=<error reading variable>) at ../src/M3Syntax.m3:295
> #12 0x0000000000414ad4 in M3File__DumpInterface (M3_CjySNq_t=<error reading variable>, M3_Bd56fi_dirPath=<error reading variable>,
>      M3_AicXUJ_updateMakefile=<error reading variable>) at ../src/M3File.m3:78
> #13 0x000000000040f3f9 in Fields__Do__MakeFieldsFiles.1150 () at ../AMD64_LINUX/Fields.m3:526
> #14 0x000000000040a713 in Fields__Do (M3_DsEykq_xml=<error reading variable>, M3_Bd56fi_versionString=<error reading variable>,
>      M3_Bd56fi_beginStringV=<error reading variable>, M3_D9m5ya_fieldTbl=<error reading variable>, M3_Bd56fi_Dir=<error reading variable>,
>      M3_Bd56fi_SrcDir=<error reading variable>, M3_AZx9O5_binaryFields=<error reading variable>, M3_CebKnt_specialFields=<error reading variable>,
>      M3_CT76zs_checkedTypes=<error reading variable>) at ../AMD64_LINUX/Fields.m3:538
> #15 0x0000000000413948 in Main_M3 (M3_AcxOUs_mode=<error reading variable>) at ../AMD64_LINUX/Main.m3:431
> #16 0x00000000004742ad in RTLinker__RunMainBody (M3_DjPxE3_m=<error reading variable>) at ../src/runtime/common/RTLinker.m3:408
> #17 0x0000000000473638 in RTLinker__AddUnitI (M3_DjPxE3_m=<error reading variable>) at ../src/runtime/common/RTLinker.m3:115
> #18 0x00000000004736cc in RTLinker__AddUnit (M3_DjPxE5_b=<error reading variable>) at ../src/runtime/common/RTLinker.m3:124
> #19 0x0000000000405df8 in main (argc=8, argv=0x7fffffffe2b8, envp=0x7fffffffe300) at _m3main.c:22
> (gdb)
>
> I believe all the TextStats operations are killing the performance.  Can we remove them?
>
> Here is SetChars:
>
> PROCEDURE SetChars (VAR a: ARRAY OF CHAR;  t: T;  start: CARDINAL) =
>    BEGIN
>      TextStats.NoteGround (TextStats.Op.SetChars);
>      TextStats.NoteGround (TextStats.Op.get_chars);
>      t.get_chars (a, start);
>      TextStats.NoteFinished (TextStats.Op.get_chars);
>      TextStats.NoteFinished (TextStats.Op.SetChars);
>    END SetChars;
>
> I'm not sure how best to do this.  Removing them without killing functionality might not be
> easy.  Looks like a case for conditional compilation.
>
> Maybe generate the .m3s from some other source, with and without the TextStats, depending on
> a setting in m3makefile?
>
> Second best would be to have a boolean flag in Text.m3 so the TextStats never get called.

Try the fix I just checked in to TextClass.m3.  It was already set up with such a boolean flag
(TextClass.CollectStats, set FALSE), but in one of the instrumentation procedures, two system
calls were outside the test thereof.  Hopefully, this will give a good bit of relief for now,
with a simple fix.

>
>       Mika
>
>