You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@trafficserver.apache.org by zw...@apache.org on 2014/01/08 19:49:35 UTC

git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Updated Branches:
  refs/heads/master 7549b2945 -> 5df2cac38


TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
tracking absolute time when the cache started (finished initialization).
Until cache is available, or no cache configured, this metric stays at
a value of "0".


Project: http://git-wip-us.apache.org/repos/asf/trafficserver/repo
Commit: http://git-wip-us.apache.org/repos/asf/trafficserver/commit/5df2cac3
Tree: http://git-wip-us.apache.org/repos/asf/trafficserver/tree/5df2cac3
Diff: http://git-wip-us.apache.org/repos/asf/trafficserver/diff/5df2cac3

Branch: refs/heads/master
Commit: 5df2cac3846d7d2f9ae255b051f748d25773a8bc
Parents: 7549b29
Author: Leif Hedstrom <zw...@apache.org>
Authored: Tue Jan 7 16:37:10 2014 -0700
Committer: Leif Hedstrom <zw...@apache.org>
Committed: Wed Jan 8 11:20:44 2014 -0700

----------------------------------------------------------------------
 CHANGES               | 5 +++++
 mgmt/RecordsConfig.cc | 2 ++
 proxy/Main.cc         | 4 ++++
 3 files changed, 11 insertions(+)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5df2cac3/CHANGES
----------------------------------------------------------------------
diff --git a/CHANGES b/CHANGES
index af6a08a..d5d9a9e 100644
--- a/CHANGES
+++ b/CHANGES
@@ -1,6 +1,11 @@
                                                          -*- coding: utf-8 -*-
 Changes with Apache Traffic Server 4.2.0
 
+  *) [TS-2483] Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
+   tracking absolute time when the cache started (finished
+   initialization). Until cache is available, or no cache configured, this
+   metric stays at a value of "0".
+
   *) [TS-2476] Fix size_t format string.
    Author: Radim Kolar <hs...@sendmail.cz>
 

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5df2cac3/mgmt/RecordsConfig.cc
----------------------------------------------------------------------
diff --git a/mgmt/RecordsConfig.cc b/mgmt/RecordsConfig.cc
index 22161cc..f11f6b1 100644
--- a/mgmt/RecordsConfig.cc
+++ b/mgmt/RecordsConfig.cc
@@ -1368,6 +1368,8 @@ RecordElement RecordsConfig[] = {
   ,
   {RECT_NODE, "proxy.node.restarts.proxy.start_time", RECD_INT, "0", RECU_NULL, RR_NULL, RECC_NULL, NULL, RECA_NULL}
   ,
+  {RECT_NODE, "proxy.node.restarts.proxy.cache_ready_time", RECD_INT, "0", RECU_NULL, RR_NULL, RECC_NULL, NULL, RECA_NULL}
+  ,
   {RECT_NODE, "proxy.node.restarts.proxy.stop_time", RECD_INT, "0", RECU_NULL, RR_NULL, RECC_NULL, NULL, RECA_NULL}
   ,
   {RECT_NODE, "proxy.node.restarts.proxy.restart_count", RECD_INT, "0", RECU_NULL, RR_NULL, RECC_NULL, NULL, RECA_NULL}

http://git-wip-us.apache.org/repos/asf/trafficserver/blob/5df2cac3/proxy/Main.cc
----------------------------------------------------------------------
diff --git a/proxy/Main.cc b/proxy/Main.cc
index d715319..39bba18 100644
--- a/proxy/Main.cc
+++ b/proxy/Main.cc
@@ -398,6 +398,10 @@ CB_After_Cache_Init()
     Debug("http_listen", "Delayed listen enable, cache initialization finished");
     start_HttpProxyServer();
   }
+
+  time_t cache_ready_at = time(NULL);
+  RecSetRecordInt("proxy.node.restarts.proxy.cache_ready_time", cache_ready_at);
+
   // Alert the plugins the cache is initialized.
   hook = lifecycle_hooks->get(TS_LIFECYCLE_CACHE_READY_HOOK);
   while (hook) {


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by Igor Galić <i....@brainsware.org>.
> >>>> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
> >>>> tracking absolute time when the cache started (finished initialization).
> >>>> Until cache is available, or no cache configured, this metric stays at
> >>>> a value of "0".
> >>> 
> >>> Should we document this somewhere?
> >> 
> >> 
> >> Probably, but afaik, none of the other metrics are documented :-/.
> > 
> > they are listed
> > https://trafficserver.readthedocs.org/en/latest/reference/commands/traffic_line.en.html
> > 
> > J


With a beautify comment:

.. XXX: These variables need to be documented.. Volunteers? //igalic



-- 
Igor Galić

Tel: +43 (0) 664 886 22 883
Mail: i.galic@brainsware.org
URL: http://brainsware.org/
GPG: 8716 7A9F 989B ABD5 100F  4008 F266 55D6 2998 1641


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by Leif Hedstrom <zw...@apache.org>.
Ah, ok. I can add it there.

> On Jan 9, 2014, at 5:04 PM, James Peach <jp...@apache.org> wrote:
> 
>> On Jan 9, 2014, at 2:51 PM, Leif Hedstrom <zw...@apache.org> wrote:
>> 
>>> On Jan 9, 2014, at 3:39 PM, Igor Galić <i....@brainsware.org> wrote:
>>> 
>>> 
>>> 
>>> ----- Original Message -----
>>>> Updated Branches:
>>>> refs/heads/master 7549b2945 -> 5df2cac38
>>>> 
>>>> 
>>>> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
>>>> tracking absolute time when the cache started (finished initialization).
>>>> Until cache is available, or no cache configured, this metric stays at
>>>> a value of "0".
>>> 
>>> Should we document this somewhere?
>> 
>> 
>> Probably, but afaik, none of the other metrics are documented :-/.
> 
> they are listed https://trafficserver.readthedocs.org/en/latest/reference/commands/traffic_line.en.html
> 
> J

Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by James Peach <jp...@apache.org>.
On Jan 9, 2014, at 2:51 PM, Leif Hedstrom <zw...@apache.org> wrote:

> On Jan 9, 2014, at 3:39 PM, Igor Galić <i....@brainsware.org> wrote:
> 
>> 
>> 
>> ----- Original Message -----
>>> Updated Branches:
>>> refs/heads/master 7549b2945 -> 5df2cac38
>>> 
>>> 
>>> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
>>> tracking absolute time when the cache started (finished initialization).
>>> Until cache is available, or no cache configured, this metric stays at
>>> a value of "0".
>> 
>> Should we document this somewhere?
> 
> 
> Probably, but afaik, none of the other metrics are documented :-/.

they are listed https://trafficserver.readthedocs.org/en/latest/reference/commands/traffic_line.en.html

J

Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by Leif Hedstrom <zw...@apache.org>.
On Jan 9, 2014, at 3:39 PM, Igor Galić <i....@brainsware.org> wrote:

> 
> 
> ----- Original Message -----
>> Updated Branches:
>>  refs/heads/master 7549b2945 -> 5df2cac38
>> 
>> 
>> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
>> tracking absolute time when the cache started (finished initialization).
>> Until cache is available, or no cache configured, this metric stays at
>> a value of "0".
> 
> Should we document this somewhere?


Probably, but afaik, none of the other metrics are documented :-/.

— Leif


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by Igor Galić <i....@brainsware.org>.

----- Original Message -----
> Updated Branches:
>   refs/heads/master 7549b2945 -> 5df2cac38
> 
> 
> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
> tracking absolute time when the cache started (finished initialization).
> Until cache is available, or no cache configured, this metric stays at
> a value of "0".

Should we document this somewhere?

-- 
Igor Galić

Tel: +43 (0) 664 886 22 883
Mail: i.galic@brainsware.org
URL: http://brainsware.org/
GPG: 8716 7A9F 989B ABD5 100F  4008 F266 55D6 2998 1641


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by Leif Hedstrom <zw...@apache.org>.
On Jan 12, 2014, at 5:07 PM, James Peach <jp...@apache.org> wrote:

> On Jan 8, 2014, at 10:49 AM, zwoop@apache.org wrote:
> 
>> Updated Branches:
>> refs/heads/master 7549b2945 -> 5df2cac38
>> 
>> 
>> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
>> tracking absolute time when the cache started (finished initialization).
>> Until cache is available, or no cache configured, this metric stays at
>> a value of "0".
> 
> AFAICT, this makes traffic_server always crash ….


Hmmm, ok, I’ll take a look.

— Leif

> 
> 
> (lldb) bt
> * thread #3: tid = 0x86f251, 0x00007fff91a57866 libsystem_kernel.dylib`__pthread_kill + 10, name = '[ET_NET 5], stop reason = signal SIGABRT
>    frame #0: 0x00007fff91a57866 libsystem_kernel.dylib`__pthread_kill + 10
>    frame #1: 0x00007fff90ab135c libsystem_pthread.dylib`pthread_kill + 92
>    frame #2: 0x00007fff93522bba libsystem_c.dylib`abort + 125
>    frame #3: 0x000000010d93ecb5 traffic_server`ink_mutex_acquire(m=0x000000010fe69748) + 37 at ink_mutex.h:96
>    frame #4: 0x000000010d93ec49 traffic_server`rec_mutex_acquire(m=0x000000010fe69738) + 57 at RecMutex.cc:42
>    frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
>    frame #6: 0x000000010d938948 traffic_server`RecSetRecord(rec_type=RECT_NULL, name=0x000000010d96d63c, data_type=RECD_INT, data=0x000000010fe69840, data_raw=0x0000000000000000, lock=true, inc_version=true) + 968 at P_RecCore.cc:450
>    frame #7: 0x000000010d9395e3 traffic_server`RecSetRecordInt(name=0x000000010d96d63c, rec_int=1389569383, lock=true, inc_version=true) + 115 at P_RecCore.cc:497
>    frame #8: 0x000000010d71d03f traffic_server`CB_After_Cache_Init() + 191 at Main.cc:403
>    frame #9: 0x000000010d8c7b73 traffic_server`CacheProcessor::cacheInitialized(this=0x000000010df89148) + 4995 at Cache.cc:1083
>    frame #10: 0x000000010d8cb605 traffic_server`Cache::open_done(this=0x00007f818070f5b0) + 293 at Cache.cc:2235
> e {
> 
> We end up here, in lib/records/P_RecCore.cc:
>   438      } else {
>   439        // We don't need to ats_strdup() here as we will make copies of any
>   440        // strings when we marshal them into our RecMessage buffer.
>   441        RecRecord r2;
>   442        memset(&r2, 0, sizeof(RecRecord));
>   443        r2.rec_type = rec_type;
>   444        r2.name = name;
>   445        r2.data_type = (data_type != RECD_NULL) ? data_type : r1->data_type;
>   446        r2.data = *data;
>   447        if (REC_TYPE_IS_STAT(r2.rec_type) && (data_raw != NULL)) {
>   448          r2.stat_meta.data_raw = *data_raw;
>   449        }
>   450        err = send_set_message(&r2);
>   451      }
> 
> Notice that this creates a RecRecord *without* allocating it's lock. The first thing that send_set_message() does is take the lock:
> 
> frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
>   61   {
>   62     RecMessage *m;
>   63
> -> 64     rec_mutex_acquire(&(record->lock));
>   65     m = RecMessageAlloc(RECG_SET);
>   66     m = RecMessageMarshal_Realloc(m, record);
>   67     RecDebug(DL_Note, "[send] RECG_SET [%d bytes]", sizeof(RecMessageHdr) + m->o_write - m->o_start);
> (
> 
> Which asserts:
> 
> frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
>   61   {
>   62     RecMessage *m;
>   63
> -> 64     rec_mutex_acquire(&(record->lock));
>   65     m = RecMessageAlloc(RECG_SET);
>   66     m = RecMessageMarshal_Realloc(m, record);
>   67     RecDebug(DL_Note, "[send] RECG_SET [%d bytes]", sizeof(RecMessageHdr) + m->o_write - m->o_start);
> (
> 
> 
> 
> 
> 
> 


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by Leif Hedstrom <zw...@apache.org>.
On Jan 12, 2014, at 5:07 PM, James Peach <jp...@apache.org> wrote:

> On Jan 8, 2014, at 10:49 AM, zwoop@apache.org wrote:
> 
>> Updated Branches:
>> refs/heads/master 7549b2945 -> 5df2cac38
>> 
>> 
>> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
>> tracking absolute time when the cache started (finished initialization).
>> Until cache is available, or no cache configured, this metric stays at
>> a value of "0".
> 
> AFAICT, this makes traffic_server always crash ….


I’m wondering if the cache initializes before the LibRecords is setup?

— Leif


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by James Peach <jp...@apache.org>.
On Jan 8, 2014, at 10:49 AM, zwoop@apache.org wrote:

> Updated Branches:
>  refs/heads/master 7549b2945 -> 5df2cac38
> 
> 
> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
> tracking absolute time when the cache started (finished initialization).
> Until cache is available, or no cache configured, this metric stays at
> a value of "0".

AFAICT, this makes traffic_server always crash ....


(lldb) bt
* thread #3: tid = 0x86f251, 0x00007fff91a57866 libsystem_kernel.dylib`__pthread_kill + 10, name = '[ET_NET 5], stop reason = signal SIGABRT
    frame #0: 0x00007fff91a57866 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90ab135c libsystem_pthread.dylib`pthread_kill + 92
    frame #2: 0x00007fff93522bba libsystem_c.dylib`abort + 125
    frame #3: 0x000000010d93ecb5 traffic_server`ink_mutex_acquire(m=0x000000010fe69748) + 37 at ink_mutex.h:96
    frame #4: 0x000000010d93ec49 traffic_server`rec_mutex_acquire(m=0x000000010fe69738) + 57 at RecMutex.cc:42
    frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
    frame #6: 0x000000010d938948 traffic_server`RecSetRecord(rec_type=RECT_NULL, name=0x000000010d96d63c, data_type=RECD_INT, data=0x000000010fe69840, data_raw=0x0000000000000000, lock=true, inc_version=true) + 968 at P_RecCore.cc:450
    frame #7: 0x000000010d9395e3 traffic_server`RecSetRecordInt(name=0x000000010d96d63c, rec_int=1389569383, lock=true, inc_version=true) + 115 at P_RecCore.cc:497
    frame #8: 0x000000010d71d03f traffic_server`CB_After_Cache_Init() + 191 at Main.cc:403
    frame #9: 0x000000010d8c7b73 traffic_server`CacheProcessor::cacheInitialized(this=0x000000010df89148) + 4995 at Cache.cc:1083
    frame #10: 0x000000010d8cb605 traffic_server`Cache::open_done(this=0x00007f818070f5b0) + 293 at Cache.cc:2235
e {
 
We end up here, in lib/records/P_RecCore.cc:
   438      } else {
   439        // We don't need to ats_strdup() here as we will make copies of any
   440        // strings when we marshal them into our RecMessage buffer.
   441        RecRecord r2;
   442        memset(&r2, 0, sizeof(RecRecord));
   443        r2.rec_type = rec_type;
   444        r2.name = name;
   445        r2.data_type = (data_type != RECD_NULL) ? data_type : r1->data_type;
   446        r2.data = *data;
   447        if (REC_TYPE_IS_STAT(r2.rec_type) && (data_raw != NULL)) {
   448          r2.stat_meta.data_raw = *data_raw;
   449        }
   450        err = send_set_message(&r2);
   451      }

Notice that this creates a RecRecord *without* allocating it's lock. The first thing that send_set_message() does is take the lock:

frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
   61   {
   62     RecMessage *m;
   63
-> 64     rec_mutex_acquire(&(record->lock));
   65     m = RecMessageAlloc(RECG_SET);
   66     m = RecMessageMarshal_Realloc(m, record);
   67     RecDebug(DL_Note, "[send] RECG_SET [%d bytes]", sizeof(RecMessageHdr) + m->o_write - m->o_start);
(

Which asserts:

frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
   61   {
   62     RecMessage *m;
   63
-> 64     rec_mutex_acquire(&(record->lock));
   65     m = RecMessageAlloc(RECG_SET);
   66     m = RecMessageMarshal_Realloc(m, record);
   67     RecDebug(DL_Note, "[send] RECG_SET [%d bytes]", sizeof(RecMessageHdr) + m->o_write - m->o_start);
(




 


Re: git commit: TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time, tracking absolute time when the cache started (finished initialization). Until cache is available, or no cache configured, this metric stays at a value of "0".

Posted by James Peach <jp...@apache.org>.
On Jan 8, 2014, at 10:49 AM, zwoop@apache.org wrote:

> Updated Branches:
>  refs/heads/master 7549b2945 -> 5df2cac38
> 
> 
> TS-2483 Add a new metric, proxy.node.restarts.proxy.cache_ready_time,
> tracking absolute time when the cache started (finished initialization).
> Until cache is available, or no cache configured, this metric stays at
> a value of "0".

AFAICT, this makes traffic_server always crash ....


(lldb) bt
* thread #3: tid = 0x86f251, 0x00007fff91a57866 libsystem_kernel.dylib`__pthread_kill + 10, name = '[ET_NET 5], stop reason = signal SIGABRT
    frame #0: 0x00007fff91a57866 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fff90ab135c libsystem_pthread.dylib`pthread_kill + 92
    frame #2: 0x00007fff93522bba libsystem_c.dylib`abort + 125
    frame #3: 0x000000010d93ecb5 traffic_server`ink_mutex_acquire(m=0x000000010fe69748) + 37 at ink_mutex.h:96
    frame #4: 0x000000010d93ec49 traffic_server`rec_mutex_acquire(m=0x000000010fe69738) + 57 at RecMutex.cc:42
    frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
    frame #6: 0x000000010d938948 traffic_server`RecSetRecord(rec_type=RECT_NULL, name=0x000000010d96d63c, data_type=RECD_INT, data=0x000000010fe69840, data_raw=0x0000000000000000, lock=true, inc_version=true) + 968 at P_RecCore.cc:450
    frame #7: 0x000000010d9395e3 traffic_server`RecSetRecordInt(name=0x000000010d96d63c, rec_int=1389569383, lock=true, inc_version=true) + 115 at P_RecCore.cc:497
    frame #8: 0x000000010d71d03f traffic_server`CB_After_Cache_Init() + 191 at Main.cc:403
    frame #9: 0x000000010d8c7b73 traffic_server`CacheProcessor::cacheInitialized(this=0x000000010df89148) + 4995 at Cache.cc:1083
    frame #10: 0x000000010d8cb605 traffic_server`Cache::open_done(this=0x00007f818070f5b0) + 293 at Cache.cc:2235
e {
 
We end up here, in lib/records/P_RecCore.cc:
   438      } else {
   439        // We don't need to ats_strdup() here as we will make copies of any
   440        // strings when we marshal them into our RecMessage buffer.
   441        RecRecord r2;
   442        memset(&r2, 0, sizeof(RecRecord));
   443        r2.rec_type = rec_type;
   444        r2.name = name;
   445        r2.data_type = (data_type != RECD_NULL) ? data_type : r1->data_type;
   446        r2.data = *data;
   447        if (REC_TYPE_IS_STAT(r2.rec_type) && (data_raw != NULL)) {
   448          r2.stat_meta.data_raw = *data_raw;
   449        }
   450        err = send_set_message(&r2);
   451      }

Notice that this creates a RecRecord *without* allocating it's lock. The first thing that send_set_message() does is take the lock:

frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
   61   {
   62     RecMessage *m;
   63
-> 64     rec_mutex_acquire(&(record->lock));
   65     m = RecMessageAlloc(RECG_SET);
   66     m = RecMessageMarshal_Realloc(m, record);
   67     RecDebug(DL_Note, "[send] RECG_SET [%d bytes]", sizeof(RecMessageHdr) + m->o_write - m->o_start);
(

Which asserts:

frame #5: 0x000000010d93945c traffic_server`send_set_message(record=0x000000010fe69710) + 28 at P_RecCore.cc:64
   61   {
   62     RecMessage *m;
   63
-> 64     rec_mutex_acquire(&(record->lock));
   65     m = RecMessageAlloc(RECG_SET);
   66     m = RecMessageMarshal_Realloc(m, record);
   67     RecDebug(DL_Note, "[send] RECG_SET [%d bytes]", sizeof(RecMessageHdr) + m->o_write - m->o_start);
(