Squid日志中为何会有HIT，并且DIRECT的记录？

前几天，@ARGV问了这个问题《》

 

灵异乎？一般灵异吧。只要我们走近科学，没有什么不能被解释的。

 

首先说一下HIT/MISS/REFRESH_HIT这些状态是由什么决定的

其实这些状态，在代码里就是http->log_type。而这个log_type的赋值主要是这么几个地方：

第一处，clientProcessRequest中

http->log_type = clientProcessRequest2(http);

简单地说，找到了要访问的entry，就是TCP_HIT，没找到就是TCP_MISS。

第二处，clientAccessCheckDone中，如果http_access检查没有通过，设成TCP_DENIED

第三处，clientHandleIMSReply中，根据回源IMS校验结果，可能设置成TCP_REFRESH_HIT或者TCP_REFRESH_MISS

第四处，clientCacheHit中，可能由于打开/读取磁盘文件失败，设成TCP_SWAPFAIL_MISS，也有可能由于缓存了404等报错，设成TCP_NEGATIVE_HIT，或者异步刷新的原因，设成TCP_STALE_HIT，以及由于offline模式的开启，设成TCP_OFFLINE_HIT

第五处，clientProcessHit中，应答客户端的IMS，设成TCP_IMS_HIT，或者由于hit的object的store_status还不是STORE_OK，设成TCP_MISS。

 

 

再说一下这个DIRECT是哪里来的。这是http->request->hier。一般来说，没有回源就是HIER_NONE，走DNS回源的时候设成HIER_DIRECT。如果squid里面配置了peer的话，还可能是各种PARENT，或者SIBLING。

 

那么，一个没有回源的请求，为什么是DIRECT呢？这是因为，虽然这个请求找到了StoreEntry因而没有回源，但是这个找到的StoreEntry是由上一个请求引起回源的，而且回源还没有完成，那么clientProcessRequest里面会修改当前http->request->hier，改成真正引起回源那个请求（也就是http->entry->mem_obj->request）的hier。下面这段代码就是做这件事情的（省略了无关代码）

if (NULL != http->entry) {

         if (http->entry->store_status == STORE_PENDING && http->entry->mem_obj)

         {

                  if (http->entry->mem_obj->request)

                  {

                          r->hier = http->entry->mem_obj->request2->hier;

                  }

         }

}

如果是这样，按理说，只要是第一个请求回源期间，所有的请求都应该是HIT并且DIRECT才对，应该有很多的HIT/DIRECT才对。而实际上日志中的HIT/DIRECT并不多，这又是为什么呢？

原来，是刚才提到的log_type的第五处修改“clientProcessHit中，由于hit的object的store_status还不是STORE_OK，设成TCP_MISS”造成的。下面是代码

if (e->store_status != STORE_OK)

{

         http->log_type = LOG_TCP_MISS;

}

所以，很多本来是HIT，而hier又被改成了初始回源的请求的hier的请求，log_type被改回了MISS。

 

接下来是亮点：

不难推断，只要 修改hier的clientProcessRequest，到将HIT改成MISS的clientProcessHit之间，store_status突然由STORE_PENDING变成STORE_OK，就可能会产生HIT/DIRECT了。

 

这个突变会不会发生呢？

答案是会的。

首先从理论上，clientProcessHit是有clientProcessRequest调用storeClientCopy，然后回调到clientCacheHit，再调到clientProcessHit的，在storeClientCopy期间，所需的header可能在磁盘上，需要进入aufs的异步读取流程，再由aufs的回调调用clientCacheHit。这期间clientProcessRequest会暂时放弃主进程的控制权，这期间StoreEntry完全有机会变成STORE_OK（通过storeComplete函数）。

接下来，我们从日志上验证了这一点，首先在修改hier的代码中加入日志。那句debug(0, 0)会把http结构的地址记入cache.log

if (http->entry->mem_obj->request2)

{

         r->hier = http->entry->mem_obj->request2->hier;

         debug(0, 0)("passing hier to %p from %p, at %p\n", r, http->entry->mem_obj->request2, http);

}

然后在HIT改MISS的地方加入日志，如果改了或者没改，都会记录http结构的地址。

if (e->store_status != STORE_OK)

    {

        http->log_type = LOG_TCP_MISS;

        debug(0, 0)("falling back to TCP_MISS %p\n", http);

    }

    else if (http->log_type == LOG_TCP_HIT && e->mem_status == IN_MEMORY)

    {

        http->log_type = LOG_TCP_MEM_HIT;

        debug(0, 0)("not falling back to TCP_MISS %p\n", http);

    }

    else

    {

        debug(0, 0)("not falling back to TCP_MISS %p\n", http);

    }

GC来了，我们用ab打一个url，然后看cache.log

 

绝大部分改了hier的请求，都改回了MISS

2013/01/09 14:53:45| passing hier to 0x5fe5170 from 0x5e4bf80, at 0x5fe4d28

2013/01/09 14:53:45| falling back to TCP_MISS 0x5fe4d28

但是，有的请求，由于store_status变了，就没有改回MISS

2013/01/09 15:22:47| passing hier to 0x7831910 from 0x7501f80, at 0x78314c8

2013/01/09 15:22:47| not falling back to TCP_MISS 0x78314c8

这时再看访问日志，确实出现了HIT并且DIRECT

1357716167 127.0.0.1 - - [09/Jan/2013:15:22:47 +0800] "GET  HTTP/1.0" 200 3157 "-" "ApacheBench/2.3" TCP_HIT     DIRECT

小小地总结一下

这个问题是squid一个小bug，不会引起太大的不良后果，只是日志记得诡异了一些，但回源次数不会变多，因此不用担心。