Re: poor m4 hash performance

[Eric Blake]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

According to Ralf Wildenhues on 6/4/2006 2:56 PM:
> * Eric Blake wrote on Sun, Jun 04, 2006 at 05:40:05AM CEST:
>> m4: lookup mode 0 called 229730 times, 557880 compares, 348729 misses, 
>> 4672624 bytes
> 
> Am I reading this correctly in that 2.4 compares are done per lookup?
> If yes, then it looks to me like the hash is doing perfectly fine.
> (But I haven't looked up what these numbers mean.)

I am committing the patch below to CVS branch-1_4 of m4; to use it, you
must add -DDEBUG_SYM to CFLAGS.  In the output, times tracks how often
lookup_symbol was called, compares tracks how often strcmp was called,
misses tracks how often strcmp returned non-zero, and bytes tracks how
many bytes were compared inside strcmp (the numbers I quoted earlier had a
bug in that bytes was treated as min(strlen(s1),strlen(s2)), the patch
below does an accurate byte count).

> 
> If you compare the first and the other runs, aren't you just seeing the
> difference that caching makes?

It may also be the difference of frozen files, or on which files m4 is
actually invoked on.  I'd have to look more at what autom4te is doing to
invoke m4 three times.

> 
> [ coreutils ]
>> m4: lookup mode 0 called 2526799 times, 9834148 compares, 7470505 misses, 
>> 84329947 bytes
> 
> This is still not bad at 3.9 compares per call.

But it can be made better - 3.9 strcmp per call is somewhat reduced by
increasing the number of hash buckets.  The problem is whether that is the
hotspot in m4; and my experiments confirm what Paul found, that it was
slightly noticeable, but not earth-shattering.

For CVS m4, which makes 8068 definitions (combination define and pushdef)
and 229468 lookups, the difference did not really show up in the timings
whether I stuck with the default 509 or used -H9973, although it did
reduce comparisons from 558118 (2522668 bytes, 2.5 compares per lookup)
down to 219646 (2013456 bytes, less than 1 compare per lookup).  Going to
- -H99991, which was more than 10x buckets per entry, still gave 213856
comparisons (2003266 bytes), so the hashing function is generating a lot
of collisions.

For CVS coreutils, with 83303 definitions and 2526066 lookups, using
- -H99991 reduced comparisons from 9364329 (36022688 bytes, 3.5 comparisons
per lookup) to 2415937 (22883978 bytes, less than 1 compare per lookup),
but never bought me much more than .5 sec out of 30 on my machine (1.5 %
speedup, but that was with naive profiling turned on rather than an
optimized strcmp).  So having autom4te play with -H may not buy us much.
I'll report separately about potential m4 1.4.5 improvements; this mail is
just limited to the framework for testing the various ideas.

2006-06-04  Eric Blake  <address@hidden>

        * src/symtab.c (symtab_debug, symtab_print_list) [DEBUG_SYM]: Fix
        to allow compilation, for use in debugger.
        (profiles, current_mode) [DEBUG_SYM]: New variables.
        (show_profile, profile_strcmp) [DEBUG_SYM]: New methods for
        determining hash table performance.

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.2.1 (Cygwin)
Comment: Public key at home.comcast.net/~ericblake/eblake.gpg
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFEg1oC84KuGfSFAYARAhdjAJ998MIUw+UZbNCnF+Fu6MnHUk+4oQCfW5i4
y0PQDEIvFgmHSQ+dRWreLG4=
=Ujp8
-----END PGP SIGNATURE-----

Index: src/symtab.c
===================================================================
RCS file: /sources/m4/m4/src/Attic/symtab.c,v
retrieving revision 1.1.1.1.2.2
diff -u -p -r1.1.1.1.2.2 symtab.c
--- src/symtab.c        1 May 2005 11:54:12 -0000       1.1.1.1.2.2
+++ src/symtab.c        4 Jun 2006 21:54:43 -0000
@@ -1,6 +1,6 @@
 /* GNU m4 -- A simple macro processor
 
-   Copyright (C) 1989, 1990, 1991, 1992, 1993, 1994, 2003 Free
+   Copyright (C) 1989, 1990, 1991, 1992, 1993, 1994, 2003, 2006 Free
    Software Foundation, Inc.
 
    This program is free software; you can redistribute it and/or modify
@@ -33,6 +33,59 @@
 
 #include "m4.h"
 
+#ifdef DEBUG_SYM
+/* When evaluating hash table performance, this profiling code shows
+   how many collisions were encountered.  */
+
+struct profile
+{
+  int entry; /* Number of times lookup_symbol called with this mode.  */
+  int comparisons; /* Number of times strcmp was called.  */
+  int misses; /* Number of times strcmp did not return 0.  */
+  long long bytes; /* Number of bytes compared.  */
+};
+
+static struct profile profiles[5];
+static symbol_lookup current_mode;
+
+/* On exit, show a profile of symbol table performance.  */
+static void
+show_profile (void)
+{
+  int i;
+  for (i = 0; i < 5; i++)
+    {
+      fprintf(stderr, "m4: lookup mode %d called %d times, %d compares, "
+              "%d misses, %lld bytes\n",
+              i, profiles[i].entry, profiles[i].comparisons,
+              profiles[i].misses, profiles[i].bytes);
+    }
+}
+
+/* Like strcmp (S1, S2), but also track profiling statistics.  */
+static int
+profile_strcmp (const char *s1, const char *s2)
+{
+  int i = 1;
+  int result;
+  while (*s1 && *s1 == *s2)
+    {
+      s1++;
+      s2++;
+      i++;
+    }
+  result = (unsigned char) *s1 - (unsigned char) *s2;
+  profiles[current_mode].comparisons++;
+  if (result != 0)
+    profiles[current_mode].misses++;
+  profiles[current_mode].bytes += i;
+  return result;
+}
+
+# define strcmp profile_strcmp
+#endif /* DEBUG_SYM */
+
+
 /*----------------------------------------------------------------------.
 | Initialise the symbol table, by allocating the necessary storage, and |
 | zeroing all the entries.                                             |
@@ -51,6 +104,13 @@ symtab_init (void)
 
   for (i = hash_table_size; --i >= 0;)
     *s++ = NULL;
+
+#ifdef DEBUG_SYM
+  i = atexit(show_profile);
+  if (i != 0)
+    M4ERROR ((warning_status, 0,
+              "INTERNAL ERROR: Unable to show symtab profile"));
+#endif /* DEBUG_SYM */
 }
 
 /*--------------------------------------------------.
@@ -94,7 +154,7 @@ free_symbol (symbol *sym)
 | lookup_symbol ().  It basically hashes NAME to a list in the symbol    |
 | table, and searched this list for the first occurence of a symbol with  |
 | the name.                                                              |
-|                                                                        |
+|                                                                        |
 | The MODE parameter determines what lookup_symbol () will do.  It can   |
 | either just do a lookup, do a lookup and insert if not present, do an        
  |
 | insertion even if the name is already in the list, delete the first    |
@@ -109,6 +169,11 @@ lookup_symbol (const char *name, symbol_
   symbol *sym, *prev;
   symbol **spp;
 
+#if DEBUG_SYM
+  current_mode = mode;
+  profiles[mode].entry++;
+#endif /* DEBUG_SYM */
+
   h = hash (name);
   sym = symtab[h];
 
@@ -221,19 +286,19 @@ hack_all_symbols (hack_symbol *func, con
 
 #ifdef DEBUG_SYM
 
+static void symtab_print_list (int i);
+
 static void
 symtab_debug (void)
 {
-  token_type t;
   token_data td;
   const char *text;
   symbol *s;
   int delete;
+  static int i;
 
-  while ((t = next_token (&td)) != NULL)
+  while (next_token (&td) == TOKEN_WORD)
     {
-      if (t != TOKEN_WORD)
-       continue;
       text = TOKEN_DATA_TEXT (&td);
       if (*text == '_')
        {
@@ -253,20 +318,24 @@ symtab_debug (void)
       else
        (void) lookup_symbol (text, SYMBOL_INSERT);
     }
-  hack_all_symbols (dump_symbol);
+  symtab_print_list (i++);
 }
 
 static void
 symtab_print_list (int i)
 {
   symbol *sym;
+  int h;
 
-  printf ("Symbol dump #d:\n", i);
-  for (sym = symtab[i]; sym != NULL; sym = sym->next)
-    printf ("\tname %s, addr 0x%x, next 0x%x, flags%s%s\n",
-          SYMBOL_NAME (sym), sym, sym->next,
-          SYMBOL_TRACED (sym) ? " traced" : "",
-          SYMBOL_SHADOWED (sym) ? " shadowed" : "");
+  printf ("Symbol dump #%d:\n", i);
+  for (h = 0; h < hash_table_size; h++)
+    for (sym = symtab[h]; sym != NULL; sym = sym->next)
+      printf ("\tname %s, bucket %d, addr %p, next %p, "
+              "flags%s%s\n",
+              SYMBOL_NAME (sym),
+              h, sym, SYMBOL_NEXT (sym),
+              SYMBOL_TRACED (sym) ? " traced" : "",
+              SYMBOL_SHADOWED (sym) ? " shadowed" : "");
 }
 
 #endif /* DEBUG_SYM */