throughput-logging.patch 16 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483
  1. diff --git a/src/app/config/config.c b/src/app/config/config.c
  2. index deda2448b..059ab0d76 100644
  3. --- a/src/app/config/config.c
  4. +++ b/src/app/config/config.c
  5. @@ -759,6 +759,7 @@ static const config_var_t option_vars_[] = {
  6. V(TestingDirAuthVoteHSDirIsStrict, BOOL, "0"),
  7. VAR_INVIS("___UsingTestNetworkDefaults", BOOL, UsingTestNetworkDefaults_,
  8. "0"),
  9. + V(ThroughputLogFile, FILENAME, NULL),
  10. END_OF_CONFIG_VARS
  11. };
  12. @@ -3247,6 +3248,8 @@ warn_about_relative_paths(or_options_t *options)
  13. n += warn_if_option_path_is_relative("PidFile",options->PidFile);
  14. n += warn_if_option_path_is_relative("ClientOnionAuthDir",
  15. options->ClientOnionAuthDir);
  16. + n += warn_if_option_path_is_relative("ThroughputLogFile",
  17. + options->ThroughputLogFile);
  18. for (config_line_t *hs_line = options->RendConfigLines; hs_line;
  19. hs_line = hs_line->next) {
  20. diff --git a/src/app/config/or_options_st.h b/src/app/config/or_options_st.h
  21. index 32dcd9fb1..5ae69f68a 100644
  22. --- a/src/app/config/or_options_st.h
  23. +++ b/src/app/config/or_options_st.h
  24. @@ -1109,6 +1109,8 @@ struct or_options_t {
  25. **/
  26. int DormantCanceledByStartup;
  27. + char *ThroughputLogFile;
  28. +
  29. /**
  30. * Configuration objects for individual modules.
  31. *
  32. diff --git a/src/core/include.am b/src/core/include.am
  33. index 9b4b251c8..9c2796173 100644
  34. --- a/src/core/include.am
  35. +++ b/src/core/include.am
  36. @@ -27,6 +27,7 @@ LIBTOR_APP_A_SOURCES = \
  37. src/core/mainloop/mainloop_sys.c \
  38. src/core/mainloop/netstatus.c \
  39. src/core/mainloop/periodic.c \
  40. + src/core/mainloop/throughput_logging.c \
  41. src/core/or/address_set.c \
  42. src/core/or/channel.c \
  43. src/core/or/channelpadding.c \
  44. @@ -233,6 +234,7 @@ noinst_HEADERS += \
  45. src/core/mainloop/mainloop_sys.h \
  46. src/core/mainloop/netstatus.h \
  47. src/core/mainloop/periodic.h \
  48. + src/core/mainloop/throughput_logging.h \
  49. src/core/or/addr_policy_st.h \
  50. src/core/or/address_set.h \
  51. src/core/or/cell_queue_st.h \
  52. diff --git a/src/core/mainloop/connection.c b/src/core/mainloop/connection.c
  53. index 6094f33e4..39d5ac951 100644
  54. --- a/src/core/mainloop/connection.c
  55. +++ b/src/core/mainloop/connection.c
  56. @@ -71,6 +71,7 @@
  57. #include "core/mainloop/connection.h"
  58. #include "core/mainloop/mainloop.h"
  59. #include "core/mainloop/netstatus.h"
  60. +#include "core/mainloop/throughput_logging.h"
  61. #include "core/or/channel.h"
  62. #include "core/or/channeltls.h"
  63. #include "core/or/circuitbuild.h"
  64. @@ -175,7 +176,8 @@ static int connection_finished_connecting(connection_t *conn);
  65. static int connection_reached_eof(connection_t *conn);
  66. static int connection_buf_read_from_socket(connection_t *conn,
  67. ssize_t *max_to_read,
  68. - int *socket_error);
  69. + int *socket_error,
  70. + monotime_coarse_t *now);
  71. static int connection_process_inbuf(connection_t *conn, int package_partial);
  72. static void client_check_address_changed(tor_socket_t sock);
  73. static void set_constrained_socket_buffers(tor_socket_t sock, int size);
  74. @@ -3580,7 +3582,9 @@ connection_handle_read_impl(connection_t *conn)
  75. conn->timestamp_last_read_allowed = approx_time();
  76. - connection_bucket_refill_single(conn, monotime_coarse_get_stamp());
  77. + monotime_coarse_t now;
  78. + monotime_coarse_get(&now);
  79. + connection_bucket_refill_single(conn, monotime_coarse_to_stamp(&now));
  80. switch (conn->type) {
  81. case CONN_TYPE_OR_LISTENER:
  82. @@ -3607,7 +3611,7 @@ connection_handle_read_impl(connection_t *conn)
  83. tor_assert(!conn->marked_for_close);
  84. before = buf_datalen(conn->inbuf);
  85. - if (connection_buf_read_from_socket(conn, &max_to_read, &socket_error) < 0) {
  86. + if (connection_buf_read_from_socket(conn, &max_to_read, &socket_error, &now) < 0) {
  87. /* There's a read error; kill the connection.*/
  88. if (conn->type == CONN_TYPE_OR) {
  89. connection_or_notify_error(TO_OR_CONN(conn),
  90. @@ -3704,7 +3708,7 @@ connection_handle_read(connection_t *conn)
  91. */
  92. static int
  93. connection_buf_read_from_socket(connection_t *conn, ssize_t *max_to_read,
  94. - int *socket_error)
  95. + int *socket_error, monotime_coarse_t *now)
  96. {
  97. int result;
  98. ssize_t at_most = *max_to_read;
  99. @@ -3802,6 +3806,7 @@ connection_buf_read_from_socket(connection_t *conn, ssize_t *max_to_read,
  100. tor_tls_get_n_raw_bytes(or_conn->tls, &n_read, &n_written);
  101. log_debug(LD_GENERAL, "After TLS read of %d: %ld read, %ld written",
  102. result, (long)n_read, (long)n_written);
  103. + log_recv_bytes(result, now);
  104. } else if (conn->linked) {
  105. if (conn->linked_conn) {
  106. result = buf_move_to_buf(conn->inbuf, conn->linked_conn->outbuf,
  107. @@ -4009,7 +4014,9 @@ connection_handle_write_impl(connection_t *conn, int force)
  108. conn->timestamp_last_write_allowed = now;
  109. - connection_bucket_refill_single(conn, monotime_coarse_get_stamp());
  110. + monotime_coarse_t now_coarse;
  111. + monotime_coarse_get(&now_coarse);
  112. + connection_bucket_refill_single(conn, monotime_coarse_to_stamp(&now_coarse));
  113. /* Sometimes, "writable" means "connected". */
  114. if (connection_state_is_connecting(conn)) {
  115. @@ -4148,6 +4155,7 @@ connection_handle_write_impl(connection_t *conn, int force)
  116. * the *_buf_tls functions, we should make them return ssize_t or size_t
  117. * or something. */
  118. result = (int)(initial_size-buf_datalen(conn->outbuf));
  119. + log_sent_bytes(result, &now_coarse);
  120. } else {
  121. CONN_LOG_PROTECT(conn,
  122. result = buf_flush_to_socket(conn->outbuf, conn->s,
  123. diff --git a/src/core/mainloop/mainloop.c b/src/core/mainloop/mainloop.c
  124. index c47e44077..48b415db5 100644
  125. --- a/src/core/mainloop/mainloop.c
  126. +++ b/src/core/mainloop/mainloop.c
  127. @@ -57,6 +57,7 @@
  128. #include "core/mainloop/mainloop.h"
  129. #include "core/mainloop/netstatus.h"
  130. #include "core/mainloop/periodic.h"
  131. +#include "core/mainloop/throughput_logging.h"
  132. #include "core/or/channel.h"
  133. #include "core/or/channelpadding.h"
  134. #include "core/or/channeltls.h"
  135. @@ -2339,6 +2340,14 @@ do_main_loop(void)
  136. periodic_events_connect_all();
  137. + bool logging_throughput = (get_options()->ThroughputLogFile != NULL &&
  138. + strlen(get_options()->ThroughputLogFile) != 0);
  139. +
  140. + if (logging_throughput) {
  141. + init_throughput_logging(1);
  142. + init_thread_throughput_logging(0);
  143. + }
  144. +
  145. struct timeval one_second = { 1, 0 };
  146. initialize_periodic_events_event = tor_evtimer_new(
  147. tor_libevent_get_base(),
  148. @@ -2391,7 +2400,15 @@ do_main_loop(void)
  149. }
  150. #endif /* defined(ENABLE_RESTART_DEBUGGING) */
  151. - return run_main_loop_until_done();
  152. + int rv = run_main_loop_until_done();
  153. +
  154. + if (logging_throughput) {
  155. + destroy_thread_throughput_logging();
  156. + write_throughput_log(get_options()->ThroughputLogFile);
  157. + destroy_throughput_logging();
  158. + }
  159. +
  160. + return rv;
  161. }
  162. #ifndef _WIN32
  163. diff --git a/src/core/mainloop/throughput_logging.c b/src/core/mainloop/throughput_logging.c
  164. new file mode 100644
  165. index 000000000..ee99de1e5
  166. --- /dev/null
  167. +++ b/src/core/mainloop/throughput_logging.c
  168. @@ -0,0 +1,271 @@
  169. +#include <stdbool.h>
  170. +#include <stddef.h>
  171. +#include <stdint.h>
  172. +#include <stdio.h>
  173. +#include <string.h>
  174. +#include <sys/time.h>
  175. +
  176. +#include "core/mainloop/throughput_logging.h"
  177. +
  178. +#include "lib/lock/compat_mutex.h"
  179. +#include "lib/smartlist_core/smartlist_core.h"
  180. +#include "lib/thread/threads.h"
  181. +#include "lib/malloc/malloc.h"
  182. +#include "lib/log/util_bug.h"
  183. +
  184. +const unsigned int timestep_ms = 500;
  185. +
  186. +bool throughput_logging_enabled = false;
  187. +monotime_coarse_t throughput_logging_coarse_start_time;
  188. +// NOTE: we don't lock these variables, so make sure they are set
  189. +// before any threads have started, and that they don't change
  190. +// while threads are running
  191. +
  192. +double throughput_logging_wall_start_time;
  193. +tor_mutex_t throughput_logging_lock;
  194. +
  195. +smartlist_t **sent_lists = NULL;
  196. +smartlist_t **recv_lists = NULL;
  197. +tor_mutex_t *bytes_list_mutexes = NULL;
  198. +int relay_bytes_lists_len = -1;
  199. +
  200. +tor_threadlocal_t thread_sent_list;
  201. +tor_threadlocal_t thread_recv_list;
  202. +tor_threadlocal_t thread_logging_mutex;
  203. +
  204. +// only call if no threads are running
  205. +void
  206. +init_throughput_logging(int num_threads)
  207. +{
  208. + tor_assert(!throughput_logging_enabled);
  209. +
  210. + tor_mutex_init(&throughput_logging_lock);
  211. + tor_mutex_acquire(&throughput_logging_lock);
  212. +
  213. + relay_bytes_lists_len = num_threads;
  214. +
  215. + monotime_coarse_get(&throughput_logging_coarse_start_time);
  216. + struct timeval ts;
  217. + gettimeofday(&ts, NULL);
  218. + throughput_logging_wall_start_time = ts.tv_sec+(ts.tv_usec/1000000.0);
  219. +
  220. + sent_lists = tor_malloc_zero(num_threads*sizeof(smartlist_t *));
  221. + recv_lists = tor_malloc_zero(num_threads*sizeof(smartlist_t *));
  222. + bytes_list_mutexes = tor_malloc_zero(num_threads*sizeof(tor_mutex_t));
  223. + for (int i=0; i<num_threads; i++) {
  224. + tor_mutex_init(&bytes_list_mutexes[i]);
  225. + tor_mutex_acquire(&bytes_list_mutexes[i]);
  226. + sent_lists[i] = smartlist_new();
  227. + recv_lists[i] = smartlist_new();
  228. + tor_mutex_release(&bytes_list_mutexes[i]);
  229. + }
  230. +
  231. + tor_threadlocal_init(&thread_sent_list);
  232. + tor_threadlocal_init(&thread_recv_list);
  233. + tor_threadlocal_init(&thread_logging_mutex);
  234. +
  235. + throughput_logging_enabled = true;
  236. + tor_mutex_release(&throughput_logging_lock);
  237. +}
  238. +
  239. +// only call if no threads are running
  240. +void
  241. +destroy_throughput_logging(void)
  242. +{
  243. + tor_assert(throughput_logging_enabled);
  244. +
  245. + tor_mutex_acquire(&throughput_logging_lock);
  246. +
  247. + for (int i=0; i<relay_bytes_lists_len; i++) {
  248. + tor_mutex_acquire(&bytes_list_mutexes[i]);
  249. +
  250. + smartlist_free(sent_lists[i]);
  251. + smartlist_free(recv_lists[i]);
  252. + sent_lists[i] = NULL;
  253. + recv_lists[i] = NULL;
  254. +
  255. + tor_mutex_release(&bytes_list_mutexes[i]);
  256. + tor_mutex_uninit(&bytes_list_mutexes[i]);
  257. + }
  258. +
  259. + tor_free(bytes_list_mutexes);
  260. + tor_free(sent_lists);
  261. + tor_free(recv_lists);
  262. + relay_bytes_lists_len = -1;
  263. +
  264. + tor_threadlocal_destroy(&thread_sent_list);
  265. + tor_threadlocal_destroy(&thread_recv_list);
  266. + tor_threadlocal_destroy(&thread_logging_mutex);
  267. +
  268. + throughput_logging_enabled = false;
  269. +
  270. + tor_mutex_release(&throughput_logging_lock);
  271. + tor_mutex_uninit(&throughput_logging_lock);
  272. +}
  273. +
  274. +void
  275. +init_thread_throughput_logging(int thread_id)
  276. +{
  277. + tor_assert(throughput_logging_enabled);
  278. +
  279. + tor_mutex_acquire(&throughput_logging_lock);
  280. +
  281. + tor_assert(thread_id < relay_bytes_lists_len && thread_id >= 0);
  282. + tor_threadlocal_set(&thread_logging_mutex, &bytes_list_mutexes[thread_id]);
  283. + tor_mutex_acquire(&bytes_list_mutexes[thread_id]);
  284. + // we acquire this mutex for the lifetime of the thread, hope nobody
  285. + // tries to acquire it :)
  286. +
  287. + tor_threadlocal_set(&thread_sent_list, sent_lists[thread_id]);
  288. + tor_threadlocal_set(&thread_recv_list, recv_lists[thread_id]);
  289. +
  290. + tor_mutex_release(&throughput_logging_lock);
  291. +}
  292. +
  293. +void
  294. +destroy_thread_throughput_logging(void)
  295. +{
  296. + tor_assert(throughput_logging_enabled);
  297. +
  298. + tor_threadlocal_set(&thread_sent_list, NULL);
  299. + tor_threadlocal_set(&thread_recv_list, NULL);
  300. +
  301. + tor_mutex_t *mutex = tor_threadlocal_get(&thread_logging_mutex);
  302. + if (mutex != NULL) {
  303. + tor_mutex_release(mutex);
  304. + tor_threadlocal_set(&thread_logging_mutex, NULL);
  305. + }
  306. +}
  307. +
  308. +static void
  309. +log_throughput(smartlist_t *list, uint32_t bytes, monotime_coarse_t *time)
  310. +{
  311. + tor_assert(throughput_logging_enabled);
  312. +
  313. + int64_t ms_since_start = monotime_coarse_diff_msec(&throughput_logging_coarse_start_time, time);
  314. + int list_index = ms_since_start/timestep_ms;
  315. +
  316. + if (list_index >= smartlist_len(list)) {
  317. + // need to grow the list
  318. + int additional_elements = (60000-1)/timestep_ms + 1;
  319. + // want an extra 60 seconds, and we want the ceil
  320. + int new_size = (list_index+1)+additional_elements;
  321. + // want enough room to store the current value, plus an extra 60 seconds
  322. + smartlist_grow(list, new_size);
  323. + }
  324. +
  325. + uint32_t old_bytes = (intptr_t)smartlist_get(list, list_index);
  326. + uint32_t new_bytes = old_bytes+bytes;
  327. + if (new_bytes < old_bytes) {
  328. + new_bytes = UINT32_MAX;
  329. + }
  330. + smartlist_set(list, list_index, (void *)(intptr_t)new_bytes);
  331. +}
  332. +
  333. +void
  334. +log_sent_bytes(uint32_t bytes, monotime_coarse_t *now)
  335. +{
  336. + if (bytes > 0 && throughput_logging_enabled) {
  337. + smartlist_t *sent_list = tor_threadlocal_get(&thread_sent_list);
  338. + tor_assert(sent_list != NULL);
  339. + log_throughput(sent_list, bytes, now);
  340. + }
  341. +}
  342. +
  343. +void
  344. +log_recv_bytes(uint32_t bytes, monotime_coarse_t *now)
  345. +{
  346. + if (bytes > 0 && throughput_logging_enabled) {
  347. + smartlist_t *recv_list = tor_threadlocal_get(&thread_recv_list);
  348. + tor_assert(recv_list != NULL);
  349. + log_throughput(recv_list, bytes, now);
  350. + }
  351. +}
  352. +
  353. +// only run this function when the threads have finished
  354. +void
  355. +write_throughput_log(char *file_name)
  356. +{
  357. + if (!throughput_logging_enabled) {
  358. + log_warn(LD_CONFIG, "Throughput logging was not set up, so didn't write to log file");
  359. + return;
  360. + }
  361. +
  362. + tor_mutex_acquire(&throughput_logging_lock);
  363. +
  364. + if (file_name == NULL || strlen(file_name) == 0) {
  365. + log_warn(LD_CONFIG, "Was not given a file name for the throughput log");
  366. + tor_mutex_release(&throughput_logging_lock);
  367. + return;
  368. + }
  369. +
  370. + FILE *log_file = fopen(file_name, "w");
  371. +
  372. + if (log_file == NULL) {
  373. + log_warn(LD_CONFIG, "Could not open throughput log file %s", file_name);
  374. + tor_mutex_release(&throughput_logging_lock);
  375. + return;
  376. + }
  377. +
  378. + for (int i=0; i<relay_bytes_lists_len; i++) {
  379. + tor_mutex_acquire(&bytes_list_mutexes[i]);
  380. + // this will block if any threads have not finished
  381. + }
  382. +
  383. + struct timeval ts;
  384. + gettimeofday(&ts, NULL);
  385. + double current_time = ts.tv_sec+(ts.tv_usec/1000000.0);
  386. +
  387. + // write header
  388. + fprintf(log_file, "time ");
  389. + for (int i=0; i<relay_bytes_lists_len; i++) {
  390. + for (int j=0; j<2; j++) {
  391. + fprintf(log_file, ", thrd %d %s", 0, (j==0)?"sent":"recv");
  392. + }
  393. + }
  394. + fprintf(log_file, "\n");
  395. +
  396. + // write data
  397. + bool thread_had_data = true;
  398. + int time_index = 0;
  399. + while (thread_had_data) {
  400. + // write line
  401. + thread_had_data = false;
  402. + double logging_time = throughput_logging_wall_start_time+(time_index*timestep_ms/1000.0);
  403. + fprintf(log_file, "%.3f", logging_time);
  404. +
  405. + for (int i=0; i<relay_bytes_lists_len; i++) {
  406. + // write column
  407. + smartlist_t *sent_list = sent_lists[i];
  408. + smartlist_t *recv_list = recv_lists[i];
  409. + uint32_t bytes_sent = 0;
  410. + uint32_t bytes_recv = 0;
  411. +
  412. + if (time_index < smartlist_len(sent_list)) {
  413. + bytes_sent = (intptr_t)smartlist_get(sent_list, time_index);
  414. + if (logging_time <= current_time || bytes_sent != 0) {
  415. + thread_had_data = true;
  416. + }
  417. + }
  418. + if (time_index < smartlist_len(recv_list)) {
  419. + bytes_recv = (intptr_t)smartlist_get(recv_list, time_index);
  420. + if (logging_time <= current_time || bytes_recv != 0) {
  421. + thread_had_data = true;
  422. + }
  423. + }
  424. +
  425. + fprintf(log_file, ", %11"PRIu32", %11"PRIu32, bytes_sent, bytes_recv);
  426. + }
  427. +
  428. + time_index += 1;
  429. + fprintf(log_file, "\n");
  430. + }
  431. +
  432. + for (int i=0; i<relay_bytes_lists_len; i++) {
  433. + tor_mutex_release(&bytes_list_mutexes[i]);
  434. + }
  435. +
  436. + fclose(log_file);
  437. +
  438. + tor_mutex_release(&throughput_logging_lock);
  439. +}
  440. diff --git a/src/core/mainloop/throughput_logging.h b/src/core/mainloop/throughput_logging.h
  441. new file mode 100644
  442. index 000000000..3c39cd435
  443. --- /dev/null
  444. +++ b/src/core/mainloop/throughput_logging.h
  445. @@ -0,0 +1,24 @@
  446. +#ifndef MAINLOOP_THROUGHPUT_LOG_H
  447. +#define MAINLOOP_THROUGHPUT_LOG_H
  448. +
  449. +#include "lib/time/compat_time.h"
  450. +
  451. +// the main thread should run the following before any threads have been
  452. +// created
  453. +void init_throughput_logging(int num_threads);
  454. +// the main thread should run the following after all threads have completed
  455. +void destroy_throughput_logging(void);
  456. +
  457. +// each thread should run the following
  458. +void init_thread_throughput_logging(int thread_id);
  459. +void destroy_thread_throughput_logging(void);
  460. +
  461. +// each thread should log the sent and received bytes with the following
  462. +void log_sent_bytes(uint32_t bytes, monotime_coarse_t *now);
  463. +void log_recv_bytes(uint32_t bytes, monotime_coarse_t *now);
  464. +
  465. +// the file should be written to after all threads have finished but before
  466. +// calling 'destroy_throughput_logging()'
  467. +void write_throughput_log(char *file_name);
  468. +
  469. +#endif