C++11 Variadic Printf performance

Question

variadic template is introduced in c++11. And I found the printf function can be replaced using it. However, cout is used in the implementation. I am wondering if it is possible to use something else to achieve type safe but not sacrifice too much performance.

void safe_printf(const char *s)
{
    while (*s) {
        if (*s == '%') {
            if (*(s + 1) == '%') {
                ++s;
            }
            else {
                throw "invalid format string: missing arguments";
            }
        }
        std::cout << *s++;
    }
}

template<typename T, typename... Args>
void safe_printf(const char *s, T& value, Args... args)
{
    while (*s) {
        if (*s == '%') {
            if (*(s + 1) == '%') {
                ++s;
            }
            else {
                std::cout << value;
                safe_printf(s + 1, args...); // call even when *s == 0 to detect extra arguments
                return;
            }
        }
        std::cout << *s++;
    }
    throw "extra arguments provided to printf";
}

EDIT:OK as request, I perform a test to compare the performance between cout and printf. gcc version 4.8.1, x86_64-redhat-linux

#include <iostream>
#include <cstdio>
#include <ctime>
#include <string>
#include <stdint.h>
#include <sstream>

using namespace std;
int32_t val = 10;
string s = "avcccc";

void TestOne(){
    for(int i = 0; i < 1000000; i++){
        printf("This is the value: %d, %s\n", i, s.c_str());
    }
}

void TestTwo(){
    ios_base::sync_with_stdio(false);

    for(int i = 0; i < 1000000; i++){
        cout << "This is the value: " << i << ", " << s << "\n";
    }
}

int main( int argc, char * argcv[] ) 
{
    timespec start;
    clock_gettime(CLOCK_REALTIME, &start);

    TestOne();

   timespec end;
   clock_gettime(CLOCK_REALTIME, &end);

   timespec start2;
   clock_gettime(CLOCK_REALTIME, &start2);

   TestTwo();

   timespec end2;
   clock_gettime(CLOCK_REALTIME, &end2);

   int64_t d1 = ((end.tv_sec - start.tv_sec) * 1000000000) + (end.tv_nsec - start.tv_nsec);

   int64_t d2 = ((end2.tv_sec - start2.tv_sec) * 1000000000) + (end2.tv_nsec - start2.tv_nsec);

   cout << "printf:" << d1 << " cout:" << d2 <<  ", diff(prinf-cout) " << d1-d2 << endl;
}

Without turn sync_with_stdio off.

printf:242862382 cout:275197806, diff(prinf-cout) -32335424
printf:201481941 cout:226177849, diff(prinf-cout) -24695908
printf:244915215 cout:275071790, diff(prinf-cout) -30156575
printf:235603694 cout:286859058, diff(prinf-cout) -51255364
printf:230076992 cout:248738879, diff(prinf-cout) -18661887
printf:223023056 cout:246486805, diff(prinf-cout) -23463749
printf:229922272 cout:269340309, diff(prinf-cout) -39418037
printf:228955230 cout:270675387, diff(prinf-cout) -41720157
printf:228390291 cout:228521421, diff(prinf-cout) -131130
printf:248419954 cout:268399737, diff(prinf-cout) -19979783
printf:229476729 cout:254635928, diff(prinf-cout) -25159199
printf:229646751 cout:252797729, diff(prinf-cout) -23150978
printf:227093478 cout:255390754, diff(prinf-cout) -28297276
printf:199161604 cout:224850870, diff(prinf-cout) -25689266
printf:198763304 cout:225709890, diff(prinf-cout) -26946586
printf:200445025 cout:223221944, diff(prinf-cout) -22776919
printf:202760174 cout:232363225, diff(prinf-cout) -29603051
printf:201989909 cout:225384923, diff(prinf-cout) -23395014
printf:202773400 cout:221465068, diff(prinf-cout) -18691668
printf:199076506 cout:223602064, diff(prinf-cout) -24525558
printf:200153338 cout:228610432, diff(prinf-cout) -28457094
printf:202794950 cout:223272108, diff(prinf-cout) -20477158
printf:209928648 cout:232300225, diff(prinf-cout) -22371577
printf:209722611 cout:233044140, diff(prinf-cout) -23321529
printf:248807680 cout:264406580, diff(prinf-cout) -15598900
printf:242916731 cout:246345645, diff(prinf-cout) -3428914
printf:221375038 cout:252251979, diff(prinf-cout) -30876941
printf:232892684 cout:273617728, diff(prinf-cout) -40725044
printf:238734317 cout:294238303, diff(prinf-cout) -55503986
printf:243180284 cout:284243039, diff(prinf-cout) -41062755
printf:245863056 cout:270413734, diff(prinf-cout) -24550678
printf:229300100 cout:259492696, diff(prinf-cout) -30192596
printf:227563904 cout:247802177, diff(prinf-cout) -20238273
printf:206847682 cout:230084237, diff(prinf-cout) -23236555
printf:198457595 cout:227655859, diff(prinf-cout) -29198264
printf:200265832 cout:224559564, diff(prinf-cout) -24293732
printf:201723563 cout:221764167, diff(prinf-cout) -20040604
printf:203430800 cout:221937208, diff(prinf-cout) -18506408
printf:198619127 cout:222313750, diff(prinf-cout) -23694623
printf:197686981 cout:233131170, diff(prinf-cout) -35444189
printf:199909645 cout:222764002, diff(prinf-cout) -22854357
printf:198050669 cout:221853069, diff(prinf-cout) -23802400
printf:200002449 cout:222743999, diff(prinf-cout) -22741550
printf:198573481 cout:221842796, diff(prinf-cout) -23269315
printf:200349434 cout:221501830, diff(prinf-cout) -21152396
printf:202039344 cout:238001170, diff(prinf-cout) -35961826
printf:209269614 cout:223050036, diff(prinf-cout) -13780422
printf:202794419 cout:219673749, diff(prinf-cout) -16879330
printf:223558422 cout:248919110, diff(prinf-cout) -25360688
printf:204139028 cout:231116364, diff(prinf-cout) -26977336

turn off sync_with_stdio

printf:228312005 cout:203814832, diff(prinf-cout) 24497173
printf:197367087 cout:170933621, diff(prinf-cout) 26433466
printf:203728802 cout:177833838, diff(prinf-cout) 25894964
printf:205758316 cout:180175924, diff(prinf-cout) 25582392
printf:251267252 cout:218081227, diff(prinf-cout) 33186025
printf:232029455 cout:199609356, diff(prinf-cout) 32420099
printf:246392438 cout:217010908, diff(prinf-cout) 29381530
printf:241149944 cout:202337266, diff(prinf-cout) 38812678
printf:222466515 cout:195872690, diff(prinf-cout) 26593825
printf:221633699 cout:206460840, diff(prinf-cout) 15172859
printf:229958105 cout:200284936, diff(prinf-cout) 29673169
printf:227201946 cout:195657372, diff(prinf-cout) 31544574
printf:244297134 cout:219042472, diff(prinf-cout) 25254662
printf:251881002 cout:216385940, diff(prinf-cout) 35495062
printf:227101117 cout:205227849, diff(prinf-cout) 21873268
printf:203951925 cout:177981416, diff(prinf-cout) 25970509
printf:201715048 cout:178496585, diff(prinf-cout) 23218463
printf:197549273 cout:175482278, diff(prinf-cout) 22066995
printf:239984907 cout:203745670, diff(prinf-cout) 36239237
printf:205235507 cout:181894912, diff(prinf-cout) 23340595
printf:203233202 cout:178961277, diff(prinf-cout) 24271925
printf:206434353 cout:173567831, diff(prinf-cout) 32866522
printf:202660160 cout:176737473, diff(prinf-cout) 25922687
printf:201831315 cout:175735846, diff(prinf-cout) 26095469
printf:200164787 cout:175192017, diff(prinf-cout) 24972770
printf:202584304 cout:177037255, diff(prinf-cout) 25547049
printf:204783650 cout:177513872, diff(prinf-cout) 27269778
printf:241033670 cout:220023173, diff(prinf-cout) 21010497
printf:247117709 cout:189569108, diff(prinf-cout) 57548601
printf:248105314 cout:219065335, diff(prinf-cout) 29039979
printf:236633133 cout:212964896, diff(prinf-cout) 23668237
printf:223496747 cout:195898087, diff(prinf-cout) 27598660
printf:224936154 cout:199397373, diff(prinf-cout) 25538781
printf:234572132 cout:216805022, diff(prinf-cout) 17767110
printf:246738504 cout:216305235, diff(prinf-cout) 30433269
printf:250904282 cout:217312285, diff(prinf-cout) 33591997
printf:208721377 cout:181195577, diff(prinf-cout) 27525800
printf:236245042 cout:203088785, diff(prinf-cout) 33156257
printf:204058026 cout:179401451, diff(prinf-cout) 24656575
printf:201038295 cout:176858089, diff(prinf-cout) 24180206
printf:204590031 cout:186586920, diff(prinf-cout) 18003111
printf:200774025 cout:177748984, diff(prinf-cout) 23025041
printf:203636203 cout:179084720, diff(prinf-cout) 24551483
printf:202479901 cout:179167171, diff(prinf-cout) 23312730
printf:202329892 cout:180674842, diff(prinf-cout) 21655050
printf:201305734 cout:179149029, diff(prinf-cout) 22156705
printf:200157089 cout:178860913, diff(prinf-cout) 21296176
printf:202803518 cout:177353141, diff(prinf-cout) 25450377
printf:204768180 cout:175608340, diff(prinf-cout) 29159840
printf:237805444 cout:205725465, diff(prinf-cout) 32079979

So cout can out performance printf if turn sync_with_stdio off that I have not heard sync_with_stdio before. I don't know if there is side effect for turning off.

variadic printf as above is included in the test.

void TestThree(){
   ios_base::sync_with_stdio(false);

   for(int i = 0; i < 1000000; i++){
       safe_printf("This is the value: %d, %s\n", i, s.c_str());
   }
}

Again print is still faster even sync_with_stdio is turn off that I don't quite understand.

printf:204099118 cout:684881656, diff(prinf-cout) -480782538
printf:227662054 cout:758110546, diff(prinf-cout) -530448492
printf:221534729 cout:732899502, diff(prinf-cout) -511364773
printf:203223553 cout:669386010, diff(prinf-cout) -466162457
printf:199923091 cout:662735504, diff(prinf-cout) -462812413
printf:207555026 cout:676522292, diff(prinf-cout) -468967266
printf:204846108 cout:655571171, diff(prinf-cout) -450725063
printf:199512948 cout:660717898, diff(prinf-cout) -461204950
printf:204251614 cout:676688426, diff(prinf-cout) -472436812
printf:201601655 cout:677217080, diff(prinf-cout) -475615425
printf:200311160 cout:674022044, diff(prinf-cout) -473710884
printf:202562272 cout:658126890, diff(prinf-cout) -455564618
printf:203100080 cout:660348312, diff(prinf-cout) -457248232
printf:228058969 cout:743305386, diff(prinf-cout) -515246417
printf:223976399 cout:742205352, diff(prinf-cout) -518228953
printf:204651603 cout:681893639, diff(prinf-cout) -477242036
printf:222386690 cout:745000014, diff(prinf-cout) -522613324
printf:217610811 cout:790129902, diff(prinf-cout) -572519091
printf:224156133 cout:758849874, diff(prinf-cout) -534693741
printf:204485998 cout:660430561, diff(prinf-cout) -455944563
printf:201259591 cout:667987480, diff(prinf-cout) -466727889
printf:204473955 cout:658096409, diff(prinf-cout) -453622454
printf:201986282 cout:670503647, diff(prinf-cout) -468517365
printf:204846379 cout:687089511, diff(prinf-cout) -482243132
printf:204962342 cout:681630774, diff(prinf-cout) -476668432
printf:202546744 cout:662300255, diff(prinf-cout) -459753511
printf:220856194 cout:757583221, diff(prinf-cout) -536727027
printf:232926622 cout:837024111, diff(prinf-cout) -604097489
printf:234187491 cout:801665699, diff(prinf-cout) -567478208
printf:244214945 cout:787558503, diff(prinf-cout) -543343558
printf:220227724 cout:788444837, diff(prinf-cout) -568217113
printf:227440252 cout:754596137, diff(prinf-cout) -527155885
printf:238158449 cout:814421312, diff(prinf-cout) -576262863
printf:205372147 cout:676782112, diff(prinf-cout) -471409965
printf:197566880 cout:662635516, diff(prinf-cout) -465068636
printf:199640024 cout:726088581, diff(prinf-cout) -526448557
printf:201249659 cout:660196078, diff(prinf-cout) -458946419
printf:201578923 cout:676444130, diff(prinf-cout) -474865207
printf:201034436 cout:690638993, diff(prinf-cout) -489604557
printf:208951246 cout:682032486, diff(prinf-cout) -473081240
printf:199928991 cout:673437083, diff(prinf-cout) -473508092
printf:233538795 cout:810890687, diff(prinf-cout) -577351892
printf:243872766 cout:847098807, diff(prinf-cout) -603226041
printf:243341748 cout:769877622, diff(prinf-cout) -526535874
printf:230232172 cout:733867319, diff(prinf-cout) -503635147
printf:220371109 cout:709704232, diff(prinf-cout) -489333123
printf:251803876 cout:790624221, diff(prinf-cout) -538820345
printf:202999188 cout:910149931, diff(prinf-cout) -707150743
printf:201931656 cout:669276274, diff(prinf-cout) -467344618
printf:200511370 cout:677748018, diff(prinf-cout) -477236648

Apostrophize

Have you benchmarked this at all or is this another one of those "I haven't touched this at all, but since it isn't C I think it's slow" kind of situations? – Santamaria

No, I have not yet. Since std::count is slower than printf, the performance cannot be as fast as using printf. So I wonder if there is any replacement or smart way. – Apostrophize

@MichaelD There isn't. – Santamaria

Workarounds for MS: connect.microsoft.com/VisualStudio/feedback/details/642876/… general discussion: https://mcmap.net/q/271130/-c-cout-printing-slowly If you do any optimizations, you should do them in the calling code and pass the stream as a parameter. – Arndt

std::cout slower than printf ? I hope you have data for that ;) Last time I tried, std::cin was faster than scanf for instance... There are few catches like ios_base::sync_with_stdio. – Migdaliamigeon

ok I have the test result – Apostrophize

@MichaelD, A few years late, but for a pure variadic template implementation, see my GitHub repo: github.com/eteran/cxx11_printf :-). Supports everything but floats and has some minor extensions! – Acquaint

Answer 1

The safe_printf function by Andrei Alexandrescu is quite clever, but unfortunately has serious limitations:

1. Each argument is processed twice, once to check its validity and the second time to format it with printf. The check can be disabled in release mode to avoid overhead, but this seriously undermines safety.

2. It doesn't work with positional arguments.

There is a number of ways how you can improve on it:

1. Don't always forward formatting to printf once the argument type is established. For example, this benchmark shows that it's possible to implement integer formatting which is up to 6.7 times faster than sprintf.

2. To implement positional arguments you need to store arguments in an array because they need to be addressed by an index.

Here's an example of how it can be done:

class Arg {
 private:
  enum Type { INT, DOUBLE };
  Type type;
  union {
    int int_value;
    double dbl_value;
  } u;
 public:
  Arg(int value) : type(INT) { u.int_value = value; }
  Arg(double value) : type(DOUBLE) { u.dbl_value = value; }
  // other types
};

void do_safe_printf(const char *format, const Arg *args, size_t num_args) {
  // here we can access arguments by index
}

template <typename... Args>
void safe_printf(const char *format, const Args&... args) {
  Arg arg_array[] = {args...};
  do_safe_printf(format, arg_array, sizeof...(Args));
}

Apart from supporting positional arguments, this approach will also minimize the code bloat as all the work is done by a single function do_safe_printf while safe_printf function template only places the arguments in an array.

These and other improvements have been implemented in the fmt library. According to benchmarks it is comparable or better both in speed and compiled code size to native printf implementation

Disclaimer: I'm the author of this library.

Irritable

Looks good! Did you propose this to Boost / the std-proposals mailinglist? (the Boost license is quite similar to the BSD license). – Comber

@Comber Thanks. I didn't propose it to Boost or std-proposals, but I'll consider this. – Irritable

Disclaimer -> Respect. – Kettering

Is there an easy way the Arg class could deal with std::string? It cannot be put into a union. – Rancidity

You can store string_view (pointer + size) in Arg. It is safe because the string will exist for the duration of print call. – Irritable

Answer 2

At GoingNative2012, Andrei Alexandrescu gave an implementation of a variadic safe_printf(). He uses a two-step approach. First, check the format specifiers; and second, normalize the arguments being passed. Because the implementation delegates to printf() with checked formatters and arguments, there is no std::cout in sight and hardly any runtime overhead (the exception path should not be taken often in regular code)

Code summary:

template <typename... Ts>
int safe_printf(const char * f, const Ts&... ts) 
{
    check_printf(f, normalizeArg(ts)...);  // check format specifiers
    return printf(f, normalizeArg(ts)...); // output with clean arguments
}

void check_printf(const char * f) 
{
    // checking is O(N) in length of format specifiers
    for (; *f; ++f) {
        if (*f != ’%’ || *++f == ’%’) continue;
        throw Exc("Bad format");
    }
}

// variadic check_print(const char*, T...) omitted, see slides

template <class T>
typename enable_if<is_integral<T>::value, long>::type
normalizeArg(T arg) 
{ 
    return arg; 
}

// more overloads for float, T* and std::string omitted, see slides

Comber

Any idea if there is any complete implementation of Andrei's idea in existence? – Dyson

@Dyson I don't know! – Comber

@Dyson github.com/cppformat/cppformat - not actually an implementation of Andrei's idea, but something better =) – Irritable