2
\$\begingroup\$

Whilst writing an interpreter for Brainfuck, I had collapsed sequences of .......... to a single instruction OP_PUT (10) (Note that the . instruction in Brainfuck corresponds to a putchar() call in C. Say the byte at the current cell in Brainfuck was 'h', OP_PUT (10) would print h to stdout 10 times). In doing so, I had wondered what the performance difference would be in calling putchar() 10 times vs building a string of length 10 and calling puts() once.

Here's the code I wrote to benchmark the performance:

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <stdint.h>
#include <inttypes.h>
#include <float.h>
#include <time.h>
#include <sys/time.h>

#define MCS_TO_SEC(microseconds)    ((double)(microseconds) / 1000000.0)

typedef uint64_t timestamp_t;

static inline void putchar_many(size_t count, const char str[static count]) 
{
    for (int i = 0; i < count; i++) {
        putchar(str[i]);
    }
}

static char *generate_str(size_t size, int c)
{
    char *const str = malloc(size + 1);
    
    if (str) {
        memset(str, c, size);
        str[size - 1] = '\0';
    }

    return str;
}

static timestamp_t get_posix_clock_time_fallback(void)
{
    struct timeval tv;

    if (gettimeofday (&tv, NULL) == 0) {
        return (timestamp_t) (tv.tv_sec * 1000000 + tv.tv_usec);
    }
    return 0;
}

/* Reference: https://stackoverflow.com/a/37920181/20017547 */
static timestamp_t get_posix_clock_time(void)
{
#ifdef _POSIX_MONOTONIC_CLOCK
    struct timespec ts;

    if (clock_gettime (CLOCK_MONOTONIC, &ts) == 0) {
        return (timestamp_t) (ts.tv_sec * 1000000 + ts.tv_nsec / 1000);
    } 
    return get_posix_clock_time_fallback();
#else
    return get_posix_clock_time_fallback();
#endif /* _POSIX_MONOTONIC_CLOCK */
}

static inline timestamp_t get_clock_difftime(timestamp_t t0, timestamp_t t1)
{
    return t1 - t0;
}

static void benchmark_puts_vs_putchar_many(size_t strlen)
{
    char *const str = generate_str(strlen, 'X');

    if (str == NULL) {
        perror("malloc()");
        exit(EXIT_FAILURE);
    }

    timestamp_t t0 = get_posix_clock_time();
    puts(str);
    timestamp_t t1 = get_posix_clock_time();

    double puts_msecs = get_clock_difftime(t0, t1);
    
    timestamp_t t2 = get_posix_clock_time();
    putchar_many(strlen, str);
    timestamp_t t3 = get_posix_clock_time();

    double putchar_msecs = get_clock_difftime(t2, t3);
     
    fprintf(stderr,
            "| %-11zu | %-21.*f | %-29.*f |\n",
            strlen,
            FLT_DECIMAL_DIG,
            MCS_TO_SEC(puts_msecs),
            FLT_DECIMAL_DIG,
            MCS_TO_SEC(putchar_msecs));
    free(str);
}

int main(void) 
{
    fprintf(stderr,
            "|-------------|-----------------------|-------------------------------|\n"
            "| String Size | Time (puts) (seconds) | Time (putchar_many) (seconds) | \n"
            "|-------------|-----------------------|-------------------------------|\n"); 
    benchmark_puts_vs_putchar_many(1);
    benchmark_puts_vs_putchar_many(2);
    benchmark_puts_vs_putchar_many(5);
    benchmark_puts_vs_putchar_many(10);
    benchmark_puts_vs_putchar_many(100);
    benchmark_puts_vs_putchar_many(1000);
    benchmark_puts_vs_putchar_many(10000);
    benchmark_puts_vs_putchar_many(100000);
    benchmark_puts_vs_putchar_many(1000000);
    benchmark_puts_vs_putchar_many(10000000);
    benchmark_puts_vs_putchar_many(100000000);
    benchmark_puts_vs_putchar_many(1000000000);
    benchmark_puts_vs_putchar_many(10000000000);
    benchmark_puts_vs_putchar_many(100000000000);
    benchmark_puts_vs_putchar_many(1000000000000);

    fprintf(stderr, 
            "|-------------|-----------------------|-------------------------------|\n");
    return EXIT_SUCCESS;
}

Compiled with -O3 -march=native, these are the results:

|-------------|-----------------------|-------------------------------|
| String Size | Time (puts) (seconds) | Time (putchar_many) (seconds) | 
|-------------|-----------------------|-------------------------------|
| 1           | 0.000040000           | 0.000001000                   |
| 2           | 0.000000000           | 0.000001000                   |
| 5           | 0.000001000           | 0.000000000                   |
| 10          | 0.000000000           | 0.000001000                   |
| 100         | 0.000000000           | 0.000002000                   |
| 1000        | 0.000001000           | 0.000011000                   |
| 10000       | 0.000009000           | 0.000229000                   |
| 100000      | 0.000017000           | 0.001388000                   |
| 1000000     | 0.000224000           | 0.013781000                   |
| 10000000    | 0.002739000           | 0.125450000                   |
| 100000000   | 0.021062000           | 1.188414000                   |
| 1000000000  | 0.204244000           | 12.139592000                  |
malloc(): Cannot allocate memory

and some system information:

OS: Linux Mint 21.2 x86_64 
Host: VMware Virtual Platform None 
Kernel: 5.15.0-94-generic 
CPU: Intel i5-8350U (2) @ 1.896GHz 
GPU: 00:0f.0 VMware SVGA II Adapter 
Memory: 791MiB / 2933MiB 

Review Request:

Are the calculations and the functions for determining the execution time of the functions correct? How can I improve the benchmarking code?

\$\endgroup\$

1 Answer 1

2
\$\begingroup\$
  1. If you really are trying to output one character n times, and not n distinct characters, I would make putchar_many take the count and the char only. And then charge the allocation/free time to the puts() variant.
  2. puts() also puts a newline. If you don't want that, use fputs(). (At which point, you might what putc() instead of putchar(), just to be equivalent.)
  3. Also test with fwrite(). It should be faster than fputs, as it doesn't do a strlen().
  4. Also test with write(). It should be faster still.
  5. You should be invoking fflush(stdout) to finish the output. This should be charged to each variant.
  6. You should experiment with the buffer sizes (setvbuf())

Also, generate_str() is buggy in the line str[size - 1] = '\0'; There should be no -1. (Or was that compensation for the newline?)

There is a question of where you are sending the output. Are you redirecting to /dev/null? (you should be.)

There is also an issue of granularity of time. You should also be repeating each test many times. Perhaps target at least 5 seconds in each test. The overhead times (malloc/memset/free/fflush) might or might not be repeated, depending on your use case.


And finally, the problem. I just checked my systems (GCC 10.2.1, GLIBC 2.31;also GCC 4.7, GLIBC 2.13), and the implementation of putc() and putchar() are defective (at least as far as I am concerned). They are supposed to be macros. Back in version 7 Unix, they were macros. (I remember being fascinated by the implementation.) They are supposed to be FAST. Now, because of threading and/or C++ and/or other extension issues, they are just function calls.

Thus, the slowness you are seeing with putchar() is all the function calls.

\$\endgroup\$
6
  • \$\begingroup\$ Yes, I completely forgot about fwrite(). For a string of size 1000000000, puts() finishes in 0.205 seconds, putc_many() in 10.8311, and fwrite() in 0.0000120. \$\endgroup\$
    – Harith
    Commented Mar 17 at 20:35
  • \$\begingroup\$ fputs(), not puts(). And write() stays at 0.000003000 in all but 2 cases. \$\endgroup\$
    – Harith
    Commented Mar 17 at 20:50
  • \$\begingroup\$ Which is why you need a large number of repeats. And I forgot one test case: No output at all, but otherwise going through the motions. This determines what your overhead is. Note that you might need to use separate compilation units to prevent optimizing out function calls and loops. \$\endgroup\$
    – David G.
    Commented Mar 17 at 20:56
  • \$\begingroup\$ It turns out that Linux does not even validate the buffer if you are writing to /dev/null. Though it does check that it is below 0x7ffffffff000 (just shy of 128TB). (I wrote a program to write memory to stdout. That's the firrst address it fails at, with the redirection.) \$\endgroup\$
    – David G.
    Commented Mar 17 at 21:10
  • \$\begingroup\$ I played around with buffer sizes. The default buffer size on my system is 8K. Increasing it to 64K reduces the time taken by putc_many() by around 22%, but doesn't do much for the others. I also didn't see any difference after increasing it above 64K. \$\endgroup\$
    – Harith
    Commented Mar 17 at 21:37

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.