On Jan 12, 2014, at 5:07 PM, James Peach <[email protected]> wrote:
> On Jan 8, 2014, at 10:49 AM, [email protected] 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);
> (
>
>
>
>
>
>
