generic-library/g3log
1
0
Fork 0
mirror of https://github.com/KjellKod/g3log.git synced 2025-01-19 08:46:42 +01:00
Code Issues Projects Releases Wiki Activity

Updated performance test in case all "buckets" hits would be in the 0ms bucket then it is shown in us instead

Browse Source
This commit is contained in:
KjellKod 2013-12-28 14:58:22 -07:00
parent e850c33354
commit 916f478267
3 changed files with 47 additions and 27 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

11
g2log/test_performance/main_threaded_mean.cpp
View File

@ -49,10 +49,11 @@ int main(int argc, char** argv)
const std::string g_measurement_dump= g_path + g_prefix_log_name + "_RESULT.txt";
std::ostringstream oss;
const int64_t us_to_s = 1000000;
oss << "\n\n" << title << " performance " << number_of_threads << " threads MEAN times\n";
oss << "Each thread running #: " << g_loop << " * " << g_iterations << " iterations of log entries" << std::endl; // worst mean case is about 10us per log entry
const size_t xtra_margin = 2;
oss << "*** It can take som time. Please wait: Approximate wait time on MY PC was: " <<number_of_threads* (long long) (g_iterations * 10 * xtra_margin / 1000000 ) << " seconds" << std::endl;
oss << "*** It can take som time. Please wait: Approximate wait time on MY PC was: " <<number_of_threads* (int64_t) (g_iterations * 10 * xtra_margin / us_to_s ) << " seconds" << std::endl;
writeTextToFile(g_measurement_dump, oss.str(), kAppend);
oss.str(""); // clear the stream
@ -60,12 +61,10 @@ int main(int argc, char** argv)
auto logger_n_handle = g2::LogWorker::createWithDefaultLogger(g_prefix_log_name, g_path);
g2::initializeLogging(logger_n_handle.worker.get());
//g2LogWorker* logger = new g2LogWorker(g_prefix_log_name, g_path);
//g2::initializeLogging(logger);
#elif defined(GOOGLE_GLOG_PERFORMANCE)
google::InitGoogleLogging(argv[0]);
#endif
auto start_time = std::chrono::steady_clock::now();
auto start_time = std::chrono::high_resolution_clock::now();
std::thread* threads = new std::thread[number_of_threads];
// kiss: just loop, create threads, store them then join
@ -82,7 +81,7 @@ int main(int argc, char** argv)
{
threads[idx].join();
}
auto application_end_time = std::chrono::steady_clock::now();
auto application_end_time = std::chrono::high_resolution_clock::now();
delete [] threads;
#if defined(G2LOG_PERFORMANCE)
@ -91,7 +90,7 @@ int main(int argc, char** argv)
google::ShutdownGoogleLogging();
#endif
auto worker_end_time = std::chrono::steady_clock::now();
auto worker_end_time = std::chrono::high_resolution_clock::now();
auto application_time_us = std::chrono::duration_cast<microsecond>(application_end_time - start_time).count();
auto total_time_us = std::chrono::duration_cast<microsecond>(worker_end_time - start_time).count();

45
g2log/test_performance/main_threaded_worst.cpp
View File

@ -76,7 +76,7 @@ int main(int argc, char** argv)
#endif
std::thread* threads = new std::thread[number_of_threads];
std::vector<long long>* threads_result = new std::vector<long long>[number_of_threads];
std::vector<int64_t>* threads_result = new std::vector<int64_t>[number_of_threads];
// kiss: just loop, create threads, store them then join
// could probably do this more elegant with lambdas
@ -121,7 +121,7 @@ int main(int argc, char** argv)
for(size_t idx = 0; idx < number_of_threads; ++idx)
{
std::vector<long long>& t_result = threads_result[idx];
std::vector<int64_t>& t_result = threads_result[idx];
auto worstUs = (*std::max_element(t_result.begin(), t_result.end()));
oss << "[Application t" << idx+1 << " worst took: " << worstUs / int64_t(1000) << " ms (" << worstUs << " us)] " << std::endl;
}
@ -129,33 +129,54 @@ int main(int argc, char** argv)
std::cout << "Result can be found at:" << g_measurement_dump << std::endl;
// now split the result in buckets of 10ms each so that it's obvious how the peaks go
std::vector<long long> all_measurements;
std::vector<int64_t> all_measurements;
all_measurements.reserve(g_iterations * number_of_threads);
for(size_t idx = 0; idx < number_of_threads; ++idx)
{
std::vector<long long>& t_result = threads_result[idx];
std::vector<int64_t>& t_result = threads_result[idx];
all_measurements.insert(all_measurements.end(), t_result.begin(), t_result.end());
}
delete [] threads_result; // finally get rid of them
std::sort (all_measurements.begin(), all_measurements.end());
std::map<long long, long long> value_amounts;
// for(long long& idx : all_measurements) --- didn't work?!
std::map<int64_t, int64_t> value_amounts;
std::map<int64_t, int64_t> value_amounts_for_0ms_bucket;
for(auto iter = all_measurements.begin(); iter != all_measurements.end(); ++iter)
{
auto value = (*iter)/us_to_ms; // convert to ms
//auto bucket=floor(value*10+0.5)/10;
++value_amounts[value]; // asuming size_t is default 0 when initialized
++value_amounts[value]; // asuming int64_t is default 0 when initialized
if(0 == value) {
++value_amounts_for_0ms_bucket[*iter];
}
}
oss.str("");
oss << "Number of values rounted to milliseconds and put to [millisecond bucket] were dumped to file: " << g_measurement_bucket_dump << std::endl;
oss << "Format: bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl;
oss << "Number of values rounded to milliseconds and put to [millisecond bucket] were dumped to file: " << g_measurement_bucket_dump << std::endl;
if(1 == value_amounts.size()) {
oss << "Format: bucket of us inside bucket0 for ms\nFormat:bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl;
oss << "\n";
}
else {
oss << "Format:bucket_of_ms, number_of_values_in_bucket\n\n" << std::endl;
}
std::cout << oss.str() << std::endl;
for(auto iter = value_amounts.begin(); iter != value_amounts.end(); ++iter)
//
// If all values are for the 0ms bucket then instead show us buckets
//
if(1 == value_amounts.size()) {
oss << "\n\n***** Microsecond bucket measurement for all measurements that went inside the '0 millisecond bucket' ****\n";
for(auto us_bucket: value_amounts_for_0ms_bucket) {
oss << us_bucket.first << "\t" << us_bucket.second << std::endl;
}
oss << "\n\n***** Millisecond bucket measurement ****\n";
}
for(auto ms_bucket: value_amounts)
{
oss << iter->first << "\t, " << iter->second << std::endl;
oss << ms_bucket.first << "\t, " << ms_bucket.second << std::endl;
}
writeTextToFile(g_measurement_bucket_dump,oss.str(), kAppend, false);

18
g2log/test_performance/performance.h
View File

@ -29,9 +29,9 @@ using namespace g2::internal;
#error G2LOG_PERFORMANCE or GOOGLE_GLOG_PERFORMANCE was not defined
#endif
typedef std::chrono::steady_clock::time_point time_point;
typedef std::chrono::duration<long,std::ratio<1, 1000> > millisecond;
typedef std::chrono::duration<long long,std::ratio<1, 1000000> > microsecond;
typedef std::chrono::high_resolution_clock::time_point time_point;
typedef std::chrono::duration<int64_t,std::ratio<1, 1000> > millisecond;
typedef std::chrono::duration<int64_t,std::ratio<1, 1000000> > microsecond;
namespace g2_test
{
@ -72,17 +72,17 @@ bool writeTextToFile(const std::string& filename, const std::string& msg, const
return true;
}
long long mean(const std::vector<long long> &v)
int64_t mean(const std::vector<int64_t> &v)
{
long long total = std::accumulate(v.begin(), v.end(), 0 ); // '0' is the initial value
int64_t total = std::accumulate(v.begin(), v.end(), 0 ); // '0' is the initial value
return total/v.size();
}
void measurePeakDuringLogWrites(const std::string& title, std::vector<long long>& result);
inline void measurePeakDuringLogWrites(const std::string& title, std::vector<long long>& result)
void measurePeakDuringLogWrites(const std::string& title, std::vector<int64_t>& result);
inline void measurePeakDuringLogWrites(const std::string& title, std::vector<int64_t>& result)
{
@ -96,9 +96,9 @@ inline void measurePeakDuringLogWrites(const std::string& title, std::vector<lon
#endif
for(size_t count = 0; count < g_iterations; ++count)
{
auto start_time = std::chrono::steady_clock::now();
auto start_time = std::chrono::high_resolution_clock::now();
LOG(INFO) << title << " iteration #" << count << " " << charptrmsg << strmsg << " and a float: " << std::setprecision(6) << pi_f;
auto stop_time = std::chrono::steady_clock::now();
auto stop_time = std::chrono::high_resolution_clock::now();
auto time_us = std::chrono::duration_cast<microsecond>(stop_time - start_time).count();
result.push_back(time_us);
}