MediaWiki r84782 - Code Review

Jump to: navigation, search
Repository:MediaWiki
Revision:r84781‎ | r84782 (on ViewVC)‎ | r84783 >
Date:00:18, 26 March 2011
Author:platonides
Status:fixme (Comments)
Tags:nodeploy 
Comment:
Added timing statistics
Modified paths:

Diff [purge]

Index: trunk/extensions/PoolCounter/daemon/stats.c
@@ -1,5 +1,6 @@
22 #include <stdio.h>
33 #include <string.h>
 4+#include <math.h>
45 #include "stats.h"
56
67
@@ -7,11 +8,13 @@
89
910 #define COMMAND(item) + sizeof(#item) + 2 + MAX_COUNT_LEN
1011 static char stats_buffer[
11 - sizeof("Uptime: 100000 days, 23h 59m 59s") + 2
 12+ sizeof("Uptime: 100000 days, 23h 59m 59s") + 2 + 700
1213 #include "stats.list"
1314 ];
1415 #undef COMMAND
1516
 17+static size_t strtimeval(char* dst, size_t max, const char* title, const struct timeval* tv);
 18+
1619 const char* provide_stats(const char* type)
1720 {
1821 int seconds = time(NULL) - stats.start;
@@ -25,6 +28,14 @@
2629 n = sprintf( stats_buffer, "uptime: %u days, %dh %dm %ds\n", days, hours, minutes, seconds );
2730
2831 if ( !strcasecmp( type, "FULL" ) ) {
 32+ n += strtimeval( stats_buffer + n, 100, "total processing time", &stats.processing_time );
 33+ n += strtimeval( stats_buffer + n, 100, "gained time", &stats.gained_time );
 34+ n += strtimeval( stats_buffer + n, 100, "waiting time", &stats.waiting_time );
 35+ n += strtimeval( stats_buffer + n, 100, "waiting time for me", &stats.waiting_time_for_me );
 36+ n += strtimeval( stats_buffer + n, 100, "waiting time for anyone", &stats.waiting_time_for_anyone );
 37+ n += strtimeval( stats_buffer + n, 100, "waiting time for good", &stats.waiting_time_for_good );
 38+ n += strtimeval( stats_buffer + n, 100, "wasted timeout time", &stats.wasted_timeout_time );
 39+
2940 #define COMMAND(item) n += sprintf( stats_buffer + n, #item ": %" PRcount "\n", stats.item );
3041 #include "stats.list"
3142 #undef COMMAND
@@ -38,3 +49,40 @@
3950 }
4051 return stats_buffer;
4152 }
 53+
 54+/**
 55+ * Writes a timeval into the string.
 56+ * It is expected to get inlined.
 57+ * @return amount of bytes written
 58+ */
 59+static size_t strtimeval(char* dst, size_t max, const char* title, const struct timeval* tv) {
 60+ int n;
 61+ n = snprintf( dst, max, "%s: ", title );
 62+ if ( max < n ) return 0;
 63+
 64+ float seconds = tv->tv_sec + tv->tv_usec * 1.0e-6f;
 65+ if ( seconds >= 60 ) {
 66+ int minutes = seconds / 60;
 67+ seconds = fmodf( seconds, 60 );
 68+
 69+ if ( minutes >= 60 ) {
 70+ int hours = minutes / 60;
 71+ minutes %= 60;
 72+
 73+ if ( hours >= 24 ) {
 74+ unsigned int days = hours / 24;
 75+
 76+ n += snprintf( dst + n, max - n, "%u days ", days );
 77+ if ( max < n ) return 0;
 78+ }
 79+ n += snprintf( dst + n, max - n, "%dh ", hours );
 80+ if ( max < n ) return 0;
 81+ }
 82+ n += snprintf( dst + n, max - n, "%dm ", minutes );
 83+ if ( max < n ) return 0;
 84+ }
 85+ n += snprintf( dst + n, max - n, "%fs\n", seconds );
 86+ if ( max < n ) return 0;
 87+
 88+ return n;
 89+}
Index: trunk/extensions/PoolCounter/daemon/locks.h
@@ -2,6 +2,7 @@
33 #define LOCKS_H
44
55 #include <stdint.h>
 6+#include <sys/time.h>
67
78 /* This application uses several double linked lists.
89 * They are circular lists, new items are added on the end (ie. on prev)
@@ -34,6 +35,7 @@
3536 struct double_linked_list siblings;
3637 struct PoolCounter* parent;
3738 enum lock_state { UNLOCKED, WAITING, WAIT_ANY, PROCESSING } state;
 39+ struct timeval timeval; /* Stores the instante where it started waiting/processing */
3840 };
3941
4042 struct client_data;
Index: trunk/extensions/PoolCounter/daemon/stats.h
@@ -1,3 +1,7 @@
 2+#ifndef _BSD_SOURCE
 3+#define _BSD_SOURCE
 4+#endif
 5+#include <sys/time.h>
26
37 #include <time.h>
48 #include <stdint.h>
@@ -10,6 +14,14 @@
1115 struct stats {
1216 time_t start;
1317
 18+ struct timeval processing_time; /* Total processing time */
 19+ struct timeval gained_time; /* Processing time saved by waiting (pairs with waiting_time_for_good) */
 20+ struct timeval waiting_time; /* Total time waiting until getting the lock (waiting_time_for_me + waiting_time_for_anyone) */
 21+ struct timeval waiting_time_for_me; /* Total time waiting until getting a lock for that item */
 22+ struct timeval waiting_time_for_anyone; /* Total time waiting until getting a lock for anyone */
 23+ struct timeval waiting_time_for_good; /* Total time waiting until another worker did the work for us */
 24+ struct timeval wasted_timeout_time; /* Waiting time of workers which finally hitted its timeout */
 25+
1426 #define COMMAND(item) volatile count_t item;
1527 #include "stats.list"
1628 #undef COMMAND
@@ -21,3 +33,13 @@
2234
2335 #define incr_stats(item) stats.item++
2436 #define decr_stats(item) stats.item--
 37+
 38+#define time_stats(lock,item) \
 39+ do { \
 40+ struct timeval tv; \
 41+ if ( !timerisset( &now ) ) { \
 42+ gettimeofday( &now, NULL ); \
 43+ } \
 44+ timersub( &now, &(lock)->timeval, &tv ); \
 45+ timeradd( &tv, &stats.item, &stats.item ); \
 46+ } while (0)
Index: trunk/extensions/PoolCounter/daemon/stats.list
@@ -10,4 +10,5 @@
1111 COMMAND(full_queues) /* Number of times locks were refused because the queue already had so many workers */
1212 COMMAND(lock_mismatch) /* Number of times a user tried to do a lock without a previous release */
1313 COMMAND(release_mismatch) /* Number of times a user tried to do a release without a previous lock */
 14+COMMAND(processed_count) /* Count of processing */
1415
Index: trunk/extensions/PoolCounter/daemon/locks.c
@@ -1,12 +1,13 @@
22 #define _XOPEN_SOURCE 500
3 -#include <string.h>
4 -#include <stdlib.h>
5 -#include <stdio.h>
 3+#include "stats.h"
64 #include "locks.h"
75 #include "hash.h"
86 #include "client_data.h"
9 -#include "stats.h"
107
 8+#include <string.h>
 9+#include <stdlib.h>
 10+#include <stdio.h>
 11+
1112 void init_lock(struct locks* l) {
1213 l->state = UNLOCKED;
1314 }
@@ -99,6 +100,7 @@
100101
101102 if ( pCounter->processing < workers ) {
102103 l->state = PROCESSING;
 104+ gettimeofday( &l->timeval, NULL );
103105 pCounter->processing++;
104106 incr_stats( processing_workers );
105107 DOUBLE_LLIST_ADD( &pCounter->working, &l->siblings );
@@ -114,6 +116,7 @@
115117 DOUBLE_LLIST_ADD( &pCounter->for_them, &l->siblings );
116118 }
117119 incr_stats( waiting_workers );
 120+ gettimeofday( &l->timeval, NULL );
118121
119122 wait_time.tv_sec = timeout;
120123 wait_time.tv_usec = 0;
@@ -139,6 +142,8 @@
140143
141144 void process_timeout(struct locks* l) {
142145 if ( ( l->state == WAIT_ANY ) || ( l->state == WAITING ) ) {
 146+ struct timeval now = { 0 };
 147+ time_stats( l, wasted_timeout_time );
143148 send_client( l, "TIMEOUT\n" );
144149 decr_stats( waiting_workers );
145150 remove_client_lock( l, 0 );
@@ -146,18 +151,25 @@
147152 }
148153
149154 void remove_client_lock(struct locks* l, int wakeup_anyones) {
 155+ struct timeval now = { 0 };
 156+
150157 DOUBLE_LLIST_DEL(&l->siblings);
151158
152159 if ( wakeup_anyones ) {
153160 while ( l->parent->for_anyone.next != &l->parent->for_anyone ) {
 161+ time_stats( (struct locks*)l->parent->for_anyone.next, waiting_time_for_good );
154162 send_client( (void*)l->parent->for_anyone.next, "DONE\n" );
155163 remove_client_lock( (void*)l->parent->for_anyone.next, 0 );
156164 decr_stats( waiting_workers );
 165+ time_stats( l, gained_time );
157166 }
158167 }
159168
160169 if ( l->state == PROCESSING ) {
161170 /* One slot freed, wake up another worker */
 171+
 172+ time_stats( l, processing_time );
 173+ incr_stats( processed_count );
162174
163175 /* Give priority to those which need to do it themselves, since
164176 * the anyones will benefit from it, too.
@@ -167,17 +179,21 @@
168180 if ( l->parent->for_them.next != &l->parent->for_them ) {
169181 /* The oldest waiting worker will be on next */
170182 new_owner = (struct locks*) l->parent->for_them.next;
 183+ time_stats( new_owner, waiting_time_for_me );
171184 } else if ( l->parent->for_anyone.next != &l->parent->for_anyone ) {
172185 new_owner = (struct locks*) l->parent->for_anyone.next;
 186+ time_stats( new_owner, waiting_time_for_anyone );
173187 }
174188
175189 if ( new_owner ) {
 190+ time_stats( new_owner, waiting_time );
176191 DOUBLE_LLIST_DEL( &new_owner->siblings );
177192 DOUBLE_LLIST_ADD( &l->parent->working, &new_owner->siblings );
178193 send_client( new_owner, "LOCKED\n" );
179194 new_owner->state = PROCESSING;
180195 incr_stats( total_acquired );
181196 decr_stats( waiting_workers );
 197+ gettimeofday( &l->timeval, NULL );
182198 } else {
183199 l->parent->processing--;
184200 decr_stats( processing_workers );
Index: trunk/extensions/PoolCounter/daemon/Makefile
@@ -2,7 +2,7 @@
33 DEFINES=-DENDIAN_BIG=0 -DENDIAN_LITTLE=1 -DHAVE_ACCEPT4=1
44 CFLAGS=-Wall $(DEFINES)
55 OBJS=main.o client_data.o locks.o hash.o stats.o
6 -LINK=-levent
 6+LINK=-levent -lm
77 HEADERS=prototypes.h client_data.h stats.h stats.list
88 DESTDIR ?=
99

Follow-up revisions

Rev.Commit summaryAuthorDate
r85438Make hours smaller!...platonides15:07, 5 April 2011

Comments

#Comment by Tim Starling (talk | contribs)   12:44, 28 March 2011

Thanks for the extra statistics.

This is not really what I meant when I said "use snprintf". This code is fragile, still has lots of integer literals, and so could easily be changed by a naive future developer in a way that makes it insecure.

Here's what I meant:

  • Make a buffer structure, which holds a data pointer, a current write pointer and a length.
  • Make a wrapper for snprintf() which takes a pointer to a buffer structure as a parameter. It should calculate the remaining length, then call snprintf() to write to the current write position. It should then advance the current write position according to the number of bytes written.
  • Make a global variable which holds such a buffer. Initialise its data pointer and length to the location of a large (say 64KB) fixed buffer. Then use this global buffer in the stats code.

I understand that this might be complicated, which is why I keep recommending the use of libevent I/O buffers.

There's no reason C code can't be secure, beautiful and readable. It's just a matter of good habits.

#Comment by Tim Starling (talk | contribs)   12:56, 28 March 2011

I think strtimeval() be better if it were rewritten to use ldiv().

http://www.cplusplus.com/reference/clibrary/cstdlib/ldiv/

Check out this time formatting code I wrote for another project:

    // Write timestamp
    ldiv_t d = {
      0,
      entry.timestamp
    };
    d = ldiv( d.rem, 3600000 );
    printZeroPad( Serial, d.quot, 4 ); // hours
    Serial.print( ':' );
    d = ldiv( d.rem, 60000 );
    printZeroPad( Serial, d.quot, 2 ); // minutes
    Serial.print( ':' );
    d = ldiv( d.rem, 1000 );
    printZeroPad( Serial, d.quot, 2 ); // seconds
    Serial.print( '.' );
    printZeroPad( Serial, d.rem, 3 ); // milliseconds
    Serial.print( ' ' );

What do you think? A number like 1/60 can't be precisely represented as a floating point number, so it's hard to verify that your code will always give the correct result.

#Comment by Tim Starling (talk | contribs)   01:23, 5 April 2011
total processing time: 188 days 4520h 57m 51.000000s
gained time: 2 days 62h 32m 52.859375s

Too many hours!

#Comment by RobLa-WMF (talk | contribs)   22:18, 30 January 2012

This is "nodeploy" only because it doesn't automatically get deployed with the rest of 1.19, but needs to be packaged and pushed.

Status & tagging log