[Bug 1391510] [NEW] sscanf extremely slow on large strings

[Shahbaz Youssefi]

Public bug reported:

This is a bug on glib, and I'm not sure if it applies upstream too
(although I suspect it does).

The bug is that `sscanf` (`vsscanf` actually) is very slow on large
strings. It _seems_ like `vsscanf` is first trying to find the end of
the string (with `rawmemchr`), which is expensive given that most of the
string is not going to be read.

Here's a test code:

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <ctype.h>

#define N 50000

static int _debug_helper(const char *src, int *a, int *n)
{
#if 1
	return sscanf(src, "%d%n", a, n);
#else
	int i = 0;
	int r = 0;
	int rseen = 0;

	while (isspace(src[i])) ++i;
	while (isdigit(src[i])) { rseen = 1; r = r * 10 + src[i++] - '0'; }

	*a = r;
	*n = i;

	return rseen;
#endif
}

int main()
{
	int i;
	int a;
	int n;
	int so_far = 0;

	char *big_string = malloc(N * 4 + 1);
	for (i = 0; i < N; ++i)
		strcpy(big_string + i * 4, "123 ");
	big_string[N * 4] = '\0';

	while (1)
	{
		if (_debug_helper(big_string + so_far, &a, &n) != 1)
			break;
		so_far += n;
	}

	return 0;
}

Compile with: gcc -Wall -g -O0 main.c

Running this code with `N = 50000` and using `sscanf`, I get:

$ time ./a.out

real    0m1.602s
user   0m1.596s
sys     0m0.000s

Running it with `N = 50000` and using the substitute code, I get:

$ time ./a.out

real    0m0.004s
user   0m0.000s
sys     0m0.000s

Which is considrably smaller. Note that this shows that the part with
`malloc` and initialization take very small time. Running callgrind
shows that almost all of the time when using `sscanf` is spent in
`rawmemchr`. Indeed, using gdb and randomly hitting CTRL+C, you always
end up with a stack trace like this:

#0  __rawmemchr_ia32 () at ../sysdeps/i386/i686/multiarch/../../rawmemchr.S:167
#1  0xb7e78a06 in _IO_str_init_static_internal () at strops.c:44
#2  0xb7e5c857 in __GI___isoc99_vsscanf () at isoc99_vsscanf.c:41
#3  0xb7e5c7cf in __isoc99_sscanf () at isoc99_sscanf.c:31
#4  0x08048494 in _debug_helper () at main.c:11
#5  0x08048517 in main () at main.c:41

This means that `rawmemchr` is slowing down `sscanf` by an unnecessary
degree. To further prove this point (and to confirm my guess that
`rawmemchr` is reading the whole string), here are a couple more tests:

With `N = 25000` and using `sscanf`:

$ time ./a.out

real    0m0.407s
user   0m0.404s
sys     0m0.000s

With `N = 12500` and using `sscanf`:

$ time ./a.out

real    0m0.106s
user   0m0.104s
sys     0m0.000s

This clearly shows an O(N^2) behavior. The main loop of the program is
`O(N)`, which means `sscanf` is running at `O(N)`. For large `N`, this
is significant. On the other hand, the actual behavior of `sscanf`
should be to read from the string according to the format string and no
more, which in this case (using `%d` and "123" as values) is of constant
time.

---

Note: I'm on Ubuntu 14.04, using gcc 4.8.2. Most importantly, this is
glibc 2.19.

** Affects: glibc (Ubuntu)
     Importance: Undecided
         Status: New


** Tags: performance

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to glibc in Ubuntu.
https://bugs.launchpad.net/bugs/1391510

Title:
  sscanf extremely slow on large strings

Status in “glibc” package in Ubuntu:
  New

Bug description:
  This is a bug on glib, and I'm not sure if it applies upstream too
  (although I suspect it does).

  The bug is that `sscanf` (`vsscanf` actually) is very slow on large
  strings. It _seems_ like `vsscanf` is first trying to find the end of
  the string (with `rawmemchr`), which is expensive given that most of
  the string is not going to be read.

  Here's a test code:

  #include <stdio.h>
  #include <stdlib.h>
  #include <string.h>
  #include <ctype.h>

  #define N 50000

  static int _debug_helper(const char *src, int *a, int *n)
  {
  #if 1
  	return sscanf(src, "%d%n", a, n);
  #else
  	int i = 0;
  	int r = 0;
  	int rseen = 0;

  	while (isspace(src[i])) ++i;
  	while (isdigit(src[i])) { rseen = 1; r = r * 10 + src[i++] - '0'; }

  	*a = r;
  	*n = i;

  	return rseen;
  #endif
  }

  int main()
  {
  	int i;
  	int a;
  	int n;
  	int so_far = 0;

  	char *big_string = malloc(N * 4 + 1);
  	for (i = 0; i < N; ++i)
  		strcpy(big_string + i * 4, "123 ");
  	big_string[N * 4] = '\0';

  	while (1)
  	{
  		if (_debug_helper(big_string + so_far, &a, &n) != 1)
  			break;
  		so_far += n;
  	}

  	return 0;
  }

  Compile with: gcc -Wall -g -O0 main.c

  Running this code with `N = 50000` and using `sscanf`, I get:

  $ time ./a.out

  real    0m1.602s
  user   0m1.596s
  sys     0m0.000s

  Running it with `N = 50000` and using the substitute code, I get:

  $ time ./a.out

  real    0m0.004s
  user   0m0.000s
  sys     0m0.000s

  Which is considrably smaller. Note that this shows that the part with
  `malloc` and initialization take very small time. Running callgrind
  shows that almost all of the time when using `sscanf` is spent in
  `rawmemchr`. Indeed, using gdb and randomly hitting CTRL+C, you always
  end up with a stack trace like this:

  #0  __rawmemchr_ia32 () at ../sysdeps/i386/i686/multiarch/../../rawmemchr.S:167
  #1  0xb7e78a06 in _IO_str_init_static_internal () at strops.c:44
  #2  0xb7e5c857 in __GI___isoc99_vsscanf () at isoc99_vsscanf.c:41
  #3  0xb7e5c7cf in __isoc99_sscanf () at isoc99_sscanf.c:31
  #4  0x08048494 in _debug_helper () at main.c:11
  #5  0x08048517 in main () at main.c:41

  This means that `rawmemchr` is slowing down `sscanf` by an unnecessary
  degree. To further prove this point (and to confirm my guess that
  `rawmemchr` is reading the whole string), here are a couple more
  tests:

  With `N = 25000` and using `sscanf`:

  $ time ./a.out

  real    0m0.407s
  user   0m0.404s
  sys     0m0.000s

  With `N = 12500` and using `sscanf`:

  $ time ./a.out

  real    0m0.106s
  user   0m0.104s
  sys     0m0.000s

  This clearly shows an O(N^2) behavior. The main loop of the program is
  `O(N)`, which means `sscanf` is running at `O(N)`. For large `N`, this
  is significant. On the other hand, the actual behavior of `sscanf`
  should be to read from the string according to the format string and
  no more, which in this case (using `%d` and "123" as values) is of
  constant time.

  ---

  Note: I'm on Ubuntu 14.04, using gcc 4.8.2. Most importantly, this is
  glibc 2.19.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/glibc/+bug/1391510/+subscriptions