xpcom/ds/nsTimelineService.cpp

   1 /* -*- Mode: C++; tab-width: 4; indent-tabs-mode: nil; c-basic-offset: 4 -*- */
   2 /* ***** BEGIN LICENSE BLOCK *****
   3  * Version: MPL 1.1/GPL 2.0/LGPL 2.1
   4  *
   5  * The contents of this file are subject to the Mozilla Public License Version
   6  * 1.1 (the "License"); you may not use this file except in compliance with
   7  * the License. You may obtain a copy of the License at
   8  * http://www.mozilla.org/MPL/
   9  *
  10  * Software distributed under the License is distributed on an "AS IS" basis,
  11  * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
  12  * for the specific language governing rights and limitations under the
  13  * License.
  14  *
  15  * The Original Code is mozilla.org code.
  16  *
  17  * The Initial Developer of the Original Code is
  18  * Netscape Communications Corporation.
  19  * Portions created by the Initial Developer are Copyright (C) 1998
  20  * the Initial Developer. All Rights Reserved.
  21  *
  22  * Contributor(s):
  23  *
  24  * Alternatively, the contents of this file may be used under the terms of
  25  * either of the GNU General Public License Version 2 or later (the "GPL"),
  26  * or the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
  27  * in which case the provisions of the GPL or the LGPL are applicable instead
  28  * of those above. If you wish to allow use of your version of this file only
  29  * under the terms of either the GPL or the LGPL, and not to allow others to
  30  * use your version of this file under the terms of the MPL, indicate your
  31  * decision by deleting the provisions above and replace them with the notice
  32  * and other provisions required by the GPL or the LGPL. If you do not delete
  33  * the provisions above, a recipient may use your version of this file under
  34  * the terms of any one of the MPL, the GPL or the LGPL.
  35  *
  36  * ***** END LICENSE BLOCK ***** */
  37
  38 #include "nsTimelineService.h"
  39 #include "prlong.h"
  40 #include "prprf.h"
  41 #include "prenv.h"
  42 #include "plhash.h"
  43 #include "prlock.h"
  44 #include "prinit.h"
  45 #include "prinrval.h"
  46 #include "prthread.h"
  47
  48 #ifdef MOZ_TIMELINE
  49
  50 #define MAXINDENT 20
  51
  52 static PRFileDesc *timelineFD = PR_STDERR;
  53 static PRBool gTimelineDisabled = PR_TRUE;
  54
  55 // Notes about threading:
  56 // We avoid locks as we always use thread-local-storage.
  57 // This means every other thread has its own private copy of
  58 // data, and this thread can't re-enter (as our implemenation
  59 // doesn't call back out anywhere).  Thus, we can avoid locks!
  60 // TLS index
  61 static const PRUintn BAD_TLS_INDEX = (PRUintn) -1;
  62 static PRUintn gTLSIndex = BAD_TLS_INDEX;
  63
  64 class TimelineThreadData {
  65 public:
  66     TimelineThreadData() : initTime(0), indent(0),
  67                            disabled(PR_TRUE), timers(nsnull) {}
  68     ~TimelineThreadData() {if (timers) PL_HashTableDestroy(timers);}
  69     PRTime initTime;
  70     PRHashTable *timers;
  71     int indent;
  72     PRBool disabled;
  73 };
  74
  75 /* Implementation file */
  76 NS_IMPL_THREADSAFE_ISUPPORTS1(nsTimelineService, nsITimelineService)
  77
  78 /*
  79  * Timer structure stored in a hash table to keep track of named
  80  * timers.
  81  */
  82 class nsTimelineServiceTimer {
  83   public:
  84     nsTimelineServiceTimer();
  85     ~nsTimelineServiceTimer();
  86     void start();
  87
  88     /*
  89      * Caller passes in "now" rather than having us calculate it so
  90      * that we can avoid including timer overhead in the time being
  91      * measured.
  92      */
  93     void stop(PRTime now);
  94     void reset();
  95     PRTime getAccum();
  96     PRTime getAccum(PRTime now);
  97
  98   private:
  99     PRTime mAccum;
 100     PRTime mStart;
 101     PRInt32 mRunning;
 102     PRThread *mOwnerThread; // only used for asserts - could be #if MOZ_DEBUG
 103 };
 104
 105 #define TIMER_CHECK_OWNER() \
 106     NS_ABORT_IF_FALSE(PR_GetCurrentThread() == mOwnerThread, \
 107                       "Timer used by non-owning thread")
 108
 109
 110 nsTimelineServiceTimer::nsTimelineServiceTimer()
 111 : mAccum(LL_ZERO), mStart(LL_ZERO), mRunning(0),
 112   mOwnerThread(PR_GetCurrentThread())
 113 {
 114 }
 115
 116 nsTimelineServiceTimer::~nsTimelineServiceTimer()
 117 {
 118 }
 119
 120 void nsTimelineServiceTimer::start()
 121 {
 122     TIMER_CHECK_OWNER();
 123     if (!mRunning) {
 124         mStart = PR_Now();
 125     }
 126     mRunning++;
 127 }
 128
 129 void nsTimelineServiceTimer::stop(PRTime now)
 130 {
 131     TIMER_CHECK_OWNER();
 132     mRunning--;
 133     if (mRunning == 0) {
 134         PRTime delta, accum;
 135         LL_SUB(delta, now, mStart);
 136         LL_ADD(accum, mAccum, delta);
 137         mAccum = accum;
 138     }
 139 }
 140
 141 void nsTimelineServiceTimer::reset()
 142 {
 143   TIMER_CHECK_OWNER();
 144   mStart = 0;
 145   mAccum = 0;
 146 }
 147
 148 PRTime nsTimelineServiceTimer::getAccum()
 149 {
 150     TIMER_CHECK_OWNER();
 151     PRTime accum;
 152
 153     if (!mRunning) {
 154         accum = mAccum;
 155     } else {
 156         PRTime delta;
 157         LL_SUB(delta, PR_Now(), mStart);
 158         LL_ADD(accum, mAccum, delta);
 159     }
 160     return accum;
 161 }
 162
 163 PRTime nsTimelineServiceTimer::getAccum(PRTime now)
 164 {
 165     TIMER_CHECK_OWNER();
 166     PRTime accum;
 167
 168     if (!mRunning) {
 169         accum = mAccum;
 170     } else {
 171         PRTime delta;
 172         LL_SUB(delta, now, mStart);
 173         LL_ADD(accum, mAccum, delta);
 174     }
 175     return accum;
 176 }
 177
 178 static TimelineThreadData *GetThisThreadData()
 179 {
 180     NS_ABORT_IF_FALSE(gTLSIndex!=BAD_TLS_INDEX, "Our TLS not initialized");
 181     TimelineThreadData *new_data = nsnull;
 182     TimelineThreadData *data = (TimelineThreadData *)PR_GetThreadPrivate(gTLSIndex);
 183     if (data == nsnull) {
 184         // First request for this thread - allocate it.
 185         new_data = new TimelineThreadData();
 186         if (!new_data)
 187             goto done;
 188
 189         // Fill it
 190         new_data->timers = PL_NewHashTable(100, PL_HashString, PL_CompareStrings,
 191                                  PL_CompareValues, NULL, NULL);
 192         if (new_data->timers==NULL)
 193             goto done;
 194         new_data->initTime = PR_Now();
 195         NS_ASSERTION(!gTimelineDisabled,
 196                          "Why are we creating new state when disabled?");
 197         new_data->disabled = PR_FALSE;
 198         data = new_data;
 199         new_data = nsnull;
 200         PR_SetThreadPrivate(gTLSIndex, data);
 201     }
 202 done:
 203     if (new_data) // eeek - error during creation!
 204         delete new_data;
 205     NS_ASSERTION(data, "TimelineService could not get thread-local data");
 206     return data;
 207 }
 208
 209 extern "C" {
 210   static void ThreadDestruct (void *data);
 211   static PRStatus TimelineInit(void);
 212 }
 213
 214 void ThreadDestruct( void *data )
 215 {
 216     if (data)
 217         delete (TimelineThreadData *)data;
 218 }
 219
 220 /*
 221 * PRCallOnceFN that initializes stuff for the timing service.
 222 */
 223 static PRCallOnceType initonce;
 224
 225 PRStatus TimelineInit(void)
 226 {
 227     char *timeStr;
 228     char *fileName;
 229     const char *timelineEnable;
 230     PRInt32 secs, msecs;
 231     PRFileDesc *fd;
 232     PRInt64 tmp1, tmp2;
 233
 234     PRStatus status = PR_NewThreadPrivateIndex( &gTLSIndex, ThreadDestruct );
 235     NS_ASSERTION(status==0, "TimelineService could not allocate TLS storage.");
 236
 237     timeStr = PR_GetEnv("NS_TIMELINE_INIT_TIME");
 238     // NS_TIMELINE_INIT_TIME only makes sense for the main thread, so if it
 239     // exists, set it there.  If not, let normal thread management code take
 240     // care of setting the init time.
 241     if (timeStr && *timeStr && (2 == PR_sscanf(timeStr, "%d.%d", &secs, &msecs))) {
 242         PRTime &initTime = GetThisThreadData()->initTime;
 243         LL_MUL(tmp1, (PRInt64)secs, 1000000);
 244         LL_MUL(tmp2, (PRInt64)msecs, 1000);
 245         LL_ADD(initTime, tmp1, tmp2);
 246     }
 247
 248     // Get the log file.
 249     fileName = PR_GetEnv("NS_TIMELINE_LOG_FILE");
 250     if (fileName && *fileName
 251         && (fd = PR_Open(fileName, PR_WRONLY | PR_CREATE_FILE | PR_TRUNCATE,
 252                          0666)) != NULL) {
 253         timelineFD = fd;
 254         PR_fprintf(fd,
 255                    "NOTE: due to asynchrony, the indentation that you see does"
 256                    " not necessarily correspond to nesting in the code.\n\n");
 257     }
 258
 259     // Runtime disable of timeline
 260     timelineEnable = PR_GetEnv("NS_TIMELINE_ENABLE");
 261     if (timelineEnable && *timelineEnable)
 262         gTimelineDisabled = PR_FALSE;
 263     return PR_SUCCESS;
 264 }
 265
 266 static void ParseTime(PRTime tm, PRInt32& secs, PRInt32& msecs)
 267 {
 268     PRTime llsecs, llmsecs, tmp;
 269
 270     LL_DIV(llsecs, tm, 1000000);
 271     LL_MOD(tmp, tm, 1000000);
 272     LL_DIV(llmsecs, tmp, 1000);
 273
 274     LL_L2I(secs, llsecs);
 275     LL_L2I(msecs, llmsecs);
 276 }
 277
 278 static char *Indent(char *buf)
 279 {
 280     int &indent = GetThisThreadData()->indent;
 281     int amount = indent;
 282     if (amount > MAXINDENT) {
 283         amount = MAXINDENT;
 284     }
 285     if (amount < 0) {
 286         amount = 0;
 287         indent = 0;
 288         PR_Write(timelineFD, "indent underflow!\n", 18);
 289     }
 290     while (amount--) {
 291         *buf++ = ' ';
 292     }
 293     return buf;
 294 }
 295
 296 static void PrintTime(PRTime tm, const char *text, va_list args)
 297 {
 298     PRInt32 secs, msecs;
 299     char pbuf[550], *pc, tbuf[550];
 300
 301     ParseTime(tm, secs, msecs);
 302
 303     // snprintf/write rather than fprintf because we don't want
 304     // messages from multiple threads to garble one another.
 305     pc = Indent(pbuf);
 306     PR_vsnprintf(pc, sizeof pbuf - (pc - pbuf), text, args);
 307     PR_snprintf(tbuf, sizeof tbuf, "%05d.%03d (%08p): %s\n",
 308                 secs, msecs, PR_GetCurrentThread(), pbuf);
 309     PR_Write(timelineFD, tbuf, strlen(tbuf));
 310 }
 311
 312 /*
 313  * Make this public if we need it.
 314  */
 315 static nsresult NS_TimelineMarkV(const char *text, va_list args)
 316 {
 317     PRTime elapsed,tmp;
 318
 319     PR_CallOnce(&initonce, TimelineInit);
 320
 321     TimelineThreadData *thread = GetThisThreadData();
 322
 323     tmp = PR_Now();
 324     LL_SUB(elapsed, tmp, thread->initTime);
 325
 326     PrintTime(elapsed, text, args);
 327
 328     return NS_OK;
 329 }
 330
 331 PR_IMPLEMENT(nsresult) NS_TimelineForceMark(const char *text, ...)
 332 {
 333     va_list args;
 334     va_start(args, text);
 335     NS_TimelineMarkV(text, args);
 336
 337     return NS_OK;
 338 }
 339
 340 PR_IMPLEMENT(nsresult) NS_TimelineMark(const char *text, ...)
 341 {
 342     va_list args;
 343     va_start(args, text);
 344
 345     PR_CallOnce(&initonce, TimelineInit);
 346
 347     if (gTimelineDisabled)
 348         return NS_ERROR_NOT_AVAILABLE;
 349
 350     TimelineThreadData *thread = GetThisThreadData();
 351
 352     if (thread->disabled)
 353         return NS_ERROR_NOT_AVAILABLE;
 354
 355     NS_TimelineMarkV(text, args);
 356
 357     return NS_OK;
 358 }
 359
 360 PR_IMPLEMENT(nsresult) NS_TimelineStartTimer(const char *timerName)
 361 {
 362     PR_CallOnce(&initonce, TimelineInit);
 363
 364     if (gTimelineDisabled)
 365         return NS_ERROR_NOT_AVAILABLE;
 366
 367     TimelineThreadData *thread = GetThisThreadData();
 368
 369     if (thread->timers == NULL)
 370         return NS_ERROR_FAILURE;
 371     if (thread->disabled)
 372         return NS_ERROR_NOT_AVAILABLE;
 373
 374     nsTimelineServiceTimer *timer
 375         = (nsTimelineServiceTimer *)PL_HashTableLookup(thread->timers, timerName);
 376     if (timer == NULL) {
 377         timer = new nsTimelineServiceTimer;
 378         if (!timer)
 379             return NS_ERROR_OUT_OF_MEMORY;
 380
 381         PL_HashTableAdd(thread->timers, timerName, timer);
 382     }
 383     timer->start();
 384     return NS_OK;
 385 }
 386
 387 PR_IMPLEMENT(nsresult) NS_TimelineStopTimer(const char *timerName)
 388 {
 389     if (gTimelineDisabled)
 390         return NS_ERROR_NOT_AVAILABLE;
 391     /*
 392      * Strange-looking now/timer->stop() interaction is to avoid
 393      * including time spent in TLS and PL_HashTableLookup in the
 394      * timer.
 395      */
 396     PRTime now = PR_Now();
 397
 398     TimelineThreadData *thread = GetThisThreadData();
 399     if (thread->timers == NULL)
 400         return NS_ERROR_FAILURE;
 401     if (thread->disabled)
 402         return NS_ERROR_NOT_AVAILABLE;
 403     nsTimelineServiceTimer *timer
 404         = (nsTimelineServiceTimer *)PL_HashTableLookup(thread->timers, timerName);
 405     if (timer == NULL) {
 406         return NS_ERROR_FAILURE;
 407     }
 408
 409     timer->stop(now);
 410
 411     return NS_OK;
 412 }
 413
 414 PR_IMPLEMENT(nsresult) NS_TimelineMarkTimer(const char *timerName, const char *str)
 415 {
 416     PR_CallOnce(&initonce, TimelineInit);
 417
 418     if (gTimelineDisabled)
 419         return NS_ERROR_NOT_AVAILABLE;
 420
 421     TimelineThreadData *thread = GetThisThreadData();
 422     if (thread->timers == NULL)
 423         return NS_ERROR_FAILURE;
 424     if (thread->disabled)
 425         return NS_ERROR_NOT_AVAILABLE;
 426     nsTimelineServiceTimer *timer
 427         = (nsTimelineServiceTimer *)PL_HashTableLookup(thread->timers, timerName);
 428     if (timer == NULL) {
 429         return NS_ERROR_FAILURE;
 430     }
 431     PRTime accum = timer->getAccum();
 432
 433     char buf[500];
 434     PRInt32 sec, msec;
 435     ParseTime(accum, sec, msec);
 436     if (!str)
 437         PR_snprintf(buf, sizeof buf, "%s total: %d.%03d",
 438                     timerName, sec, msec);
 439     else
 440         PR_snprintf(buf, sizeof buf, "%s total: %d.%03d (%s)",
 441                     timerName, sec, msec, str);
 442     NS_TimelineMark(buf);
 443
 444     return NS_OK;
 445 }
 446
 447 PR_IMPLEMENT(nsresult) NS_TimelineResetTimer(const char *timerName)
 448 {
 449     if (gTimelineDisabled)
 450         return NS_ERROR_NOT_AVAILABLE;
 451
 452     TimelineThreadData *thread = GetThisThreadData();
 453     if (thread->timers == NULL)
 454         return NS_ERROR_FAILURE;
 455     if (thread->disabled)
 456         return NS_ERROR_NOT_AVAILABLE;
 457     nsTimelineServiceTimer *timer
 458         = (nsTimelineServiceTimer *)PL_HashTableLookup(thread->timers, timerName);
 459     if (timer == NULL) {
 460         return NS_ERROR_FAILURE;
 461     }
 462
 463     timer->reset();
 464     return NS_OK;
 465 }
 466
 467 PR_IMPLEMENT(nsresult) NS_TimelineIndent()
 468 {
 469     if (gTimelineDisabled)
 470         return NS_ERROR_NOT_AVAILABLE;
 471
 472     TimelineThreadData *thread = GetThisThreadData();
 473     if (thread->disabled)
 474         return NS_ERROR_NOT_AVAILABLE;
 475     thread->indent++;
 476     return NS_OK;
 477 }
 478
 479 PR_IMPLEMENT(nsresult) NS_TimelineOutdent()
 480 {
 481     if (gTimelineDisabled)
 482         return NS_ERROR_NOT_AVAILABLE;
 483
 484     TimelineThreadData *thread = GetThisThreadData();
 485     if (thread->disabled)
 486         return NS_ERROR_NOT_AVAILABLE;
 487     thread->indent--;
 488     return NS_OK;
 489 }
 490
 491 PR_IMPLEMENT(nsresult) NS_TimelineEnter(const char *text)
 492 {
 493     nsresult rv = NS_TimelineMark("%s...", text);
 494     if (NS_FAILED(rv)) {
 495         return rv;
 496     }
 497     return NS_TimelineIndent();
 498 }
 499
 500 PR_IMPLEMENT(nsresult) NS_TimelineLeave(const char *text)
 501 {
 502     nsresult rv = NS_TimelineOutdent();
 503     if (NS_FAILED(rv)) {
 504         return rv;
 505     }
 506     return NS_TimelineMark("...%s", text);
 507 }
 508
 509 nsTimelineService::nsTimelineService()
 510 {
 511   /* member initializers and constructor code */
 512 }
 513
 514 /* void mark (in string text); */
 515 NS_IMETHODIMP nsTimelineService::Mark(const char *text)
 516 {
 517     return NS_TimelineMark(text);
 518 }
 519
 520 /* void startTimer (in string timerName); */
 521 NS_IMETHODIMP nsTimelineService::StartTimer(const char *timerName)
 522 {
 523     return NS_TimelineStartTimer(timerName);
 524 }
 525
 526 /* void stopTimer (in string timerName); */
 527 NS_IMETHODIMP nsTimelineService::StopTimer(const char *timerName)
 528 {
 529     return NS_TimelineStopTimer(timerName);
 530 }
 531
 532 /* void markTimer (in string timerName); */
 533 NS_IMETHODIMP nsTimelineService::MarkTimer(const char *timerName)
 534 {
 535     return NS_TimelineMarkTimer(timerName);
 536 }
 537
 538 /* void markTimerWithComment(in string timerName, in string comment); */
 539 NS_IMETHODIMP nsTimelineService::MarkTimerWithComment(const char *timerName, const char *comment)
 540 {
 541     return NS_TimelineMarkTimer(timerName, comment);
 542 }
 543
 544 /* void resetTimer (in string timerName); */
 545 NS_IMETHODIMP nsTimelineService::ResetTimer(const char *timerName)
 546 {
 547     return NS_TimelineResetTimer(timerName);
 548 }
 549
 550 /* void indent (); */
 551 NS_IMETHODIMP nsTimelineService::Indent()
 552 {
 553     return NS_TimelineIndent();
 554 }
 555
 556 /* void outdent (); */
 557 NS_IMETHODIMP nsTimelineService::Outdent()
 558 {
 559     return NS_TimelineOutdent();
 560 }
 561
 562 /* void enter (in string text); */
 563 NS_IMETHODIMP nsTimelineService::Enter(const char *text)
 564 {
 565     return NS_TimelineEnter(text);
 566 }
 567
 568 /* void leave (in string text); */
 569 NS_IMETHODIMP nsTimelineService::Leave(const char *text)
 570 {
 571     return NS_TimelineLeave(text);
 572 }
 573
 574 #endif /* MOZ_TIMELINE */