Using ostringstream seems to work 32+ times longer than snprintf!! Why??

[JUAN DENT]

Hi,

I am timing calls to snprintf vrs ostringstream and get an incredible result: the calls to the latter take about 32 times longer in Visual Studio 2015 Update 3!!

The code is:

void timePrintingOnBuffers()
{
	using namespace std;

	constexpr size_t max = 12;
	char buf[max];

	auto start = chrono::high_resolution_clock::now();

	for (size_t i = 0; i < 1'000'000; ++i)
	{
		snprintf(buf, max, "%d", 1200);
	}

	auto end = chrono::high_resolution_clock::now();

	auto time_taken_for_snprintf = (end - start).count();

	cout << time_taken_for_snprintf << " nanoseconds for snprintf" << endl;

	start = chrono::high_resolution_clock::now();

	for (size_t i = 0; i < 1'000'000; ++i)
	{
		ostringstream temp;
		temp << setw(4) << 1200;
		string s = temp.str();
	}

	end = chrono::high_resolution_clock::now();

	auto time_taken_for_ostringstream = (end - start).count();

	cout << time_taken_for_ostringstream  << " nanoseconds for ostringstream" << endl;

	auto relation = (long double)time_taken_for_ostringstream / time_taken_for_snprintf;

	cout << "relation: " << relation << endl;

}

Thanks for any input!!

Juan

[jlb]

Probably because you're creating new instances of those two variables 1,000,000 times in your loop for the ostringstream, but you never create any variables in that sprintf() loop. Also why are you using setw() in the ostringstream version but not using the width modifier in your sprintf() loop?

Also it would be helpful if you showed the actual output from your "program".

[Cubbi]

Let's make that comparison more fair and not constantly visit heap memory in your second loop since you don't do that in the first:

    ostringstream temp;
	for (size_t i = 0; i < 1'000'000; ++i)
	{
		temp << 1200;
                temp.seekp(0);
	}

now your test prints for me
gcc: http://coliru.stacked-crooked.com/a/77fc3bbe4d90d5d9 , local desktop similar

146401311 nanoseconds for snprintf
74096553 nanoseconds for ostringstream

but (on my desktop) vs 2015:

136668209 nanoseconds for snprintf
450268399 nanoseconds for ostringstream

It could be instructive to follow through with a profiler to see what the differences are. Microsoft implementation of streams is known to have some major flaws, but the ones I know about shouldn't apply here.

[JUAN DENT]

Ok, I replaced %d with %4d.

The output is:

646658137 nanoseconds for snprintf
14283754345 nanoseconds for ostringstream
relation: 22.0886

Yes, you are right on the fact that we are constructing and destructing a million objects in the second loop. However my concern is why the C++ standard eliminated strstream which could use an existing buffer and left only a C function for us to use?? That's why I find a ratio of about 22 in execution time to be way unacceptable.

Is there a way to reuse the ostringstream in the loop?

Thanks for your input!

Juan

[Cubbi]

PS: added boost.spirit to my demo above:

namespace bk = boost::spirit::karma;
for (size_t i = 0; i < 1'000'000; ++i)
    bk::generate(+buf, bk::lit(1200) );

gcc demo http://coliru.stacked-crooked.com/a/5bf05eb0011c5ad7

142796159 nanoseconds for snprintf
93468665 nanoseconds for ostringstream
2913784 nanoseconds for boost.karma

JUAN DENT wrote:

why the C++ standard eliminated strstream which could use an existing buffer

It didn't eliminate it. strstream is still standard C++, even in C++17. It's been deprecated back in C++98, but can't be removed until a replacement is found. (boost's array_sink is an example of such replacement: http://www.boost.org/doc/libs/1_62_0/libs/iostreams/doc/classes/array.html#array_sink )

[jlb]

It would also be helpful to know what kind of optimization you're using when you compile the code.

Using -O3
On my system(Linux using g++ version 6.1.0) using I get the following output for this code:

    ostringstream temp;
    string s;

	for (size_t i = 0; i < 1'000'000; ++i)
	{
		temp  << 1200;
		s = temp.str();
		//temp.str("");
		temp.seekp(0);
	}

 bin/Debug/testcpp
142618772 nanoseconds for snprintf
125863783 nanoseconds for ostringstream
relation: 0.882519
[jimb@acer testcpp]$ bin/Debug/testcpp
143514401 nanoseconds for snprintf
126132985 nanoseconds for ostringstream
relation: 0.878887
[jimb@acer testcpp]$ bin/Debug/testcpp
141500603 nanoseconds for snprintf
125921715 nanoseconds for ostringstream
relation: 0.889902
[jimb@acer testcpp]$ bin/Debug/testcpp
141801151 nanoseconds for snprintf
125795132 nanoseconds for ostringstream
relation: 0.887123
[jimb@acer testcpp]$ bin/Debug/testcpp
142491180 nanoseconds for snprintf
125995996 nanoseconds for ostringstream
relation: 0.884237
[jimb@acer testcpp]$ bin/Debug/testcpp
144095521 nanoseconds for snprintf
126246059 nanoseconds for ostringstream
relation: 0.876128
[jimb@acer testcpp]$ bin/Debug/testcpp
141881379 nanoseconds for snprintf
125786816 nanoseconds for ostringstream
relation: 0.886563

And for temp.str("");

bin/Debug/testcpp
142157836 nanoseconds for snprintf
136582006 nanoseconds for ostringstream
relation: 0.960777
[jimb@acer testcpp]$ bin/Debug/testcpp
142910370 nanoseconds for snprintf
134398674 nanoseconds for ostringstream
relation: 0.94044
[jimb@acer testcpp]$ bin/Debug/testcpp
142101339 nanoseconds for snprintf
136400247 nanoseconds for ostringstream
relation: 0.95988
[jimb@acer testcpp]$ bin/Debug/testcpp
142383657 nanoseconds for snprintf
132277105 nanoseconds for ostringstream
relation: 0.929019
[jimb@acer testcpp]$ bin/Debug/testcpp
143142697 nanoseconds for snprintf
131975186 nanoseconds for ostringstream
relation: 0.921983
[jimb@acer testcpp]$ bin/Debug/testcpp
143861740 nanoseconds for snprintf
138980573 nanoseconds for ostringstream
relation: 0.96607

[JUAN DENT]

Okay, using -O3 I get:

1106093393 nanoseconds for snprintf
5852622976 nanoseconds for ostringstream
relation: 5.29126

So that is better!!

Thanks,
Juan

P.S: note that is using %4d and setw(4).