サンプル1 testbench.cpp

 ログ出力にかかった時間を計測しています。

関連ファイル
  • testbench.cpp
  • Clock.hh
  • Clock.cpp
ファイルの中身

testbench.cpp

  1. #include <cstdlib>
  2. #include <cstring>
  3. #include <cstdio>
  4. #include <iostream>
  5. #include <log4cpp/Category.hh>
  6. #include <log4cpp/OstreamAppender.hh>
  7. #include <log4cpp/FileAppender.hh>
  8. #include <log4cpp/BasicLayout.hh>
  9. #include <log4cpp/PatternLayout.hh>
  10. #include <log4cpp/TimeStamp.hh>
  11. #include "Clock.hh"
  12. // -----------------------------------------------------------------------------
  13. int main(int argc, char* argv[])
  14. {
  15. int count = argc > 1 ? std::atoi(argv[1]) : 100;
  16. size_t size = argc > 2 ? std::atoi(argv[2]) : 128;
  17. std::cout << " count: " << count << std::endl
  18. << " size: " << size << " bytes" << std::endl
  19. << std::endl;
  20. log4cpp::Category& root = log4cpp::Category::getRoot();
  21. root.setPriority(log4cpp::Priority::ERROR);
  22. log4cpp::OstreamAppender ostreamAppender("cerr", &std::cerr);
  23. log4cpp::FileAppender fileAppender("stderr", fileno(stderr));
  24. ostreamAppender.setLayout(new log4cpp::BasicLayout());
  25. fileAppender.setLayout(new log4cpp::BasicLayout());
  26. root.removeAllAppenders();
  27. root.addAppender(ostreamAppender);
  28. log4cpp::Category& log = log4cpp::Category::getInstance("someCategory");
  29. Clock clock;
  30. char* buffer = new char[size + 1];
  31. std::memset(buffer, 'X', size + 1);
  32. buffer[size] = '\0';
  33. std::cout << "BasicLayout:" << std::endl;
  34. {
  35. clock.start();
  36. for (int i = 0; i < count; i++) log.error("%s", buffer);
  37. clock.stop();
  38. std::cout << " charbuf printf ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  39. }
  40. {
  41. const char* buffer2 = buffer;
  42. clock.start();
  43. for (int i = 0; i < count; i++) log.error(std::string(buffer2));
  44. clock.stop();
  45. std::cout << " charbuf string ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  46. }
  47. {
  48. std::string str(size, 'X');
  49. clock.start();
  50. for (int i = 0; i < count; i++)
  51. log << log4cpp::Priority::ERROR << str;
  52. clock.stop();
  53. std::cout << " string stream ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  54. }
  55. {
  56. clock.start();
  57. for (int i = 0; i < count; i++)
  58. log << log4cpp::Priority::ERROR << buffer;
  59. clock.stop();
  60. std::cout << " charbuf stream ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  61. }
  62. {
  63. std::string str(size, 'X');
  64. clock.start();
  65. log4cpp::CategoryStream s(log << log4cpp::Priority::ERROR);
  66. for (int i = 0; i < count; i++)
  67. s << str << log4cpp::eol;
  68. clock.stop();
  69. std::cout << " string stream2 ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  70. }
  71. {
  72. clock.start();
  73. log4cpp::CategoryStream s(log << log4cpp::Priority::ERROR);
  74. for (int i = 0; i < count; i++)
  75. s << buffer << log4cpp::eol;
  76. clock.stop();
  77. std::cout << " charbuf stream2 ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  78. }
  79. {
  80. std::string str(size, 'X');
  81. clock.start();
  82. for (int i = 0; i < count; i++) log.error(str);
  83. clock.stop();
  84. std::cout << " direct string ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  85. }
  86. {
  87. std::string str(size, 'X');
  88. root.removeAllAppenders();
  89. root.addAppender(fileAppender);
  90. clock.start();
  91. for (int i = 0; i < count; i++) log.error(str);
  92. clock.stop();
  93. std::cout << " direct string file: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  94. }
  95. std::cout << "PatternLayout:" << std::endl;
  96. {
  97. log4cpp::PatternLayout* patternLayout = new log4cpp::PatternLayout();
  98. patternLayout->setConversionPattern("%R %p %c %x: %m\n");
  99. ostreamAppender.setLayout(patternLayout);
  100. }
  101. {
  102. log4cpp::PatternLayout* patternLayout = new log4cpp::PatternLayout();
  103. patternLayout->setConversionPattern("%R %p %c %x: %m\n");
  104. fileAppender.setLayout(patternLayout);
  105. }
  106. root.removeAllAppenders();
  107. root.addAppender(ostreamAppender);
  108. {
  109. clock.start();
  110. for (int i = 0; i < count; i++) log.error("%s", buffer);
  111. clock.stop();
  112. std::cout << " charbuf printf ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  113. }
  114. {
  115. std::string str(size, 'X');
  116. clock.start();
  117. for (int i = 0; i < count; i++) log.error(str);
  118. clock.stop();
  119. std::cout << " direct string ostream: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  120. }
  121. {
  122. std::string str(size, 'X');
  123. root.removeAllAppenders();
  124. root.addAppender(fileAppender);
  125. clock.start();
  126. for (int i = 0; i < count; i++) log.error(str);
  127. clock.stop();
  128. std::cout << " string file: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  129. }
  130. {
  131. clock.start();
  132. for (int i = 0; i < count; i++) fprintf(stderr, "%d ERROR someCategory : %s\n", log4cpp::TimeStamp().getSeconds(), buffer);
  133. clock.stop();
  134. std::cout << std::endl << " fprintf: " << ((float)clock.elapsed()) / count << " us" << std::endl;
  135. }
  136. delete[] buffer;
  137. log4cpp::Category::shutdown();
  138. return 0;
  139. }

Clock.hh

  1. /* $Id: Clock.hh,v 1.5 2002/09/15 22:40:50 bastiaan Exp $
  2. *
  3. * See the COPYING file for the terms of usage and distribution.
  4. */
  5. #ifndef __CLOCK_H
  6. #define __CLOCK_H
  7. #ifdef LOG4CPP_HAVE_STDINT_H
  8. #include <stdint.h>
  9. #endif // LOG4CPP_HAVE_STDINT_H
  10. #ifdef __osf__
  11. typedef long usec_t; /* number of microseconds since 1970/01/01 */
  12. # define INT64_CONSTANT(val) (val##L)
  13. #else
  14. typedef int64_t usec_t;
  15. # define INT64_CONSTANT(val) (val##LL)
  16. #endif
  17. class Clock
  18. {
  19. public:
  20. static bool UsingCPU;
  21. static usec_t time(void);
  22. Clock(void);
  23. ~Clock(void);
  24. bool active(void) const { return _active; }
  25. usec_t elapsed(void) const;
  26. usec_t start(void);
  27. usec_t reset(void) { return start(); }
  28. usec_t stop(void);
  29. private:
  30. usec_t _start;
  31. usec_t _elapsed;
  32. bool _active;
  33. };
  34. #endif

Clock.cpp

  1. static const char rcsid[] = "$Id: Clock.cpp,v 1.9 2002/09/15 22:40:50 bastiaan Exp $";
  2. /*
  3. * See the COPYING file for the terms of usage and distribution.
  4. */
  5. #include <cstdlib>
  6. #include <sys/time.h> // for struct timeval
  7. #ifdef __osf__
  8. # include <machine/builtins.h> // for __RPCC()
  9. #elif __linux__ && __i386__
  10. # define rdtscl(low) \
  11. __asm__ __volatile__("rdtsc" : "=a" (low) : : "edx")
  12. #endif
  13. #include <iostream>
  14. #include "Clock.hh"
  15. namespace
  16. {
  17. const usec_t UsecPerSec = INT64_CONSTANT(1000000);
  18. }
  19. bool Clock::UsingCPU = std::getenv("CLOCK_USE_CPU") ? true : false;
  20. // -----------------------------------------------------------------------------
  21. usec_t Clock::time(void)
  22. {
  23. if (UsingCPU) {
  24. static bool warn = true;
  25. if (warn) {
  26. std::cout << "Using CPU clock." << std::endl;
  27. warn = false;
  28. }
  29. #ifdef __osf__
  30. return (usec_t) __RPCC();
  31. #elif __linux__ && __i386__
  32. {
  33. unsigned long tsc;
  34. rdtscl(tsc);
  35. return (usec_t) tsc;
  36. }
  37. #else
  38. {
  39. std::cerr << "CPU clock not implemented for this architecture" << std::endl;
  40. UsingCPU = false;
  41. return Clock::time();
  42. }
  43. #endif
  44. } else {
  45. struct timeval tv;
  46. gettimeofday(&tv, NULL);
  47. return (usec_t) (tv.tv_sec * UsecPerSec + tv.tv_usec);
  48. }
  49. }
  50. // -----------------------------------------------------------------------------
  51. Clock::Clock(void)
  52. : _start(0),
  53. _elapsed(0),
  54. _active(false)
  55. {
  56. start();
  57. }
  58. // -----------------------------------------------------------------------------
  59. Clock::~Clock(void)
  60. {
  61. ;
  62. }
  63. // -----------------------------------------------------------------------------
  64. usec_t Clock::elapsed(void) const
  65. {
  66. if (!active())
  67. return _elapsed;
  68. return time() - _start;
  69. }
  70. // -----------------------------------------------------------------------------
  71. usec_t Clock::start(void)
  72. {
  73. _active = true;
  74. return _start = time();
  75. }
  76. // -----------------------------------------------------------------------------
  77. usec_t Clock::stop(void)
  78. {
  79. _elapsed = elapsed();
  80. _active = false;
  81. return _elapsed;
  82. }

実行結果例

 testbench.cppをビルドし、実行した結果です。結果は環境により変わりますので、参考程度としてください。なお、実行環境はLinux(Ubuntu 11.0)です。

stdout(標準出力):

  count: 100
   size: 128 bytes

BasicLayout:
  charbuf printf  ostream:  168.27 us
  charbuf string  ostream:  180.15 us
  string  stream  ostream:  466.3 us
  charbuf stream  ostream:  316.01 us
  string  stream2 ostream:  1275.56 us
  charbuf stream2 ostream:  741.45 us
  direct  string  ostream:  680.31 us
  direct  string  file:     1354.59 us
PatternLayout:
  charbuf printf ostream:  737.43 us
  direct  string ostream:  643.69 us
  string  file:     1399.6 us

  fprintf:        714.83 us
stderr(標準エラー出力):
1336790214 ERROR someCategory : XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
が1200回出力されます。