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 ....
(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);
(
