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 2022/08/10 17:23:47 UTC
[trafficserver] branch 9.2.x updated: Update slice to only prefetch when first block is miss/hit-stale (#8890)
This is an automated email from the ASF dual-hosted git repository.
zwoop pushed a commit to branch 9.2.x
in repository https://gitbox.apache.org/repos/asf/trafficserver.git
The following commit(s) were added to refs/heads/9.2.x by this push:
new 682e372d3 Update slice to only prefetch when first block is miss/hit-stale (#8890)
682e372d3 is described below
commit 682e372d333bda20e2a9fec6d722c7fca5882a59
Author: Serris Lew <se...@gmail.com>
AuthorDate: Thu Jul 28 14:36:53 2022 -0700
Update slice to only prefetch when first block is miss/hit-stale (#8890)
* Update slice to only prefetch when first block is miss/hit-stale
* Remove extra line spaces & generalize autest output
* Verify cont is valid
* Use xdebug to only prefetch when first block is cacheable with miss/hit-stale status
* Precompile via regex pattern in config
* Remove plugin dependency, add cache status header between slice and crr
* Only enable prefetching from CRR on 206 partial case from origin
* Update header type, fix 206 case for 304 in CRR, allow header to be used for debugging
* update header val type
Co-authored-by: Serris Lew <ls...@apple.com>
(cherry picked from commit f14cce4f218f22fb395c64d6cc42bf37626b309f)
Conflicts:
doc/admin-guide/plugins/slice.en.rst
---
doc/admin-guide/plugins/slice.en.rst | 15 ++--
.../cache_range_requests/cache_range_requests.cc | 27 +++++++
plugins/experimental/slice/Data.h | 2 +-
plugins/experimental/slice/HttpHeader.h | 3 +
plugins/experimental/slice/prefetch.cc | 54 ++++++++-----
plugins/experimental/slice/prefetch.h | 17 +---
plugins/experimental/slice/server.cc | 5 ++
plugins/experimental/slice/util.cc | 27 ++++---
.../pluginTest/slice/gold/slice_prefetch.gold | 27 +++++++
.../pluginTest/slice/slice_prefetch.test.py | 92 +++++++++++++---------
10 files changed, 181 insertions(+), 88 deletions(-)
diff --git a/doc/admin-guide/plugins/slice.en.rst b/doc/admin-guide/plugins/slice.en.rst
index 73078fbbb..f9f26bdf3 100644
--- a/doc/admin-guide/plugins/slice.en.rst
+++ b/doc/admin-guide/plugins/slice.en.rst
@@ -113,13 +113,6 @@ The slice plugin supports the following options::
Requires setting up an intermediate loopback remap rule.
-r for short
- --prefetch-count=<int> (optional)
- Default is 0
- Prefetches successive 'n' slice block requests in the background
- and cached. Especially for large objects, prefetching can improve
- cache miss latency.
- -f for short
-
--skip-header=<header name> (default: X-Slicer-Info)
Header name used by the slice plugin after the loopback
to indicate that the slice plugin should be skipped.
@@ -133,6 +126,14 @@ The slice plugin supports the following options::
`cache_range_requests` plugin.
-i for short
+ --prefetch-count=<int> (optional)
+ Default is 0
+ Prefetches successive 'n' slice block requests in the background
+ and caches (with `cache_range_requests` plugin). Prefetching is only
+ enabled when first block is a cacheable object with miss or hit-stale status.
+ Especially for large objects, prefetching can improve cache miss latency.
+ -f for short
+
Examples::
@plugin=slice.so @pparam=--blockbytes=1000000 @plugin=cache_range_requests.so
diff --git a/plugins/cache_range_requests/cache_range_requests.cc b/plugins/cache_range_requests/cache_range_requests.cc
index 7c3b708b8..46539f370 100644
--- a/plugins/cache_range_requests/cache_range_requests.cc
+++ b/plugins/cache_range_requests/cache_range_requests.cc
@@ -48,6 +48,8 @@ using parent_select_mode_t = enum parent_select_mode {
};
constexpr std::string_view DefaultImsHeader = {"X-Crr-Ims"};
+constexpr std::string_view SLICE_CRR_HEADER = {"Slice-Crr-Status"};
+constexpr std::string_view SLICE_CRR_VAL = "1";
struct pluginconfig {
parent_select_mode_t ps_mode{PS_DEFAULT};
@@ -64,6 +66,8 @@ struct txndata {
time_t ims_time{0};
bool verify_cacheability{false};
bool cache_complete_responses{false};
+ bool slice_response{false};
+ bool slice_request{false};
};
// pluginconfig struct (global plugin only)
@@ -296,6 +300,13 @@ range_header_check(TSHttpTxn txnp, pluginconfig *const pc)
TSHttpTxnHookAdd(txnp, TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK, txn_contp);
DEBUG_LOG("Also Added TS_HTTP_CACHE_LOOKUP_COMPLETE_HOOK");
}
+
+ // check if slice requests for cache lookup status
+ TSMLoc const locfield(TSMimeHdrFieldFind(hdr_buf, hdr_loc, SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size()));
+ if (nullptr != locfield) {
+ TSHandleMLocRelease(hdr_buf, hdr_loc, locfield);
+ txn_state->slice_request = true;
+ }
}
TSHandleMLocRelease(hdr_buf, hdr_loc, range_loc);
} else {
@@ -370,6 +381,12 @@ handle_client_send_response(TSHttpTxn txnp, txndata *const txn_state)
DEBUG_LOG("Restoring response header to TS_HTTP_STATUS_PARTIAL_CONTENT.");
TSHttpHdrStatusSet(resp_buf, resp_loc, TS_HTTP_STATUS_PARTIAL_CONTENT);
}
+
+ remove_header(resp_buf, resp_loc, SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size());
+ if (txn_state->slice_response) {
+ set_header(resp_buf, resp_loc, SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size(), SLICE_CRR_VAL.data(),
+ SLICE_CRR_VAL.size());
+ }
} else {
DEBUG_LOG("Ignoring status code %d; txn_state->origin_status=%d", status, txn_state->origin_status);
}
@@ -404,6 +421,7 @@ handle_server_read_response(TSHttpTxn txnp, txndata *const txn_state)
{
TSMBuffer resp_buf = nullptr;
TSMLoc resp_loc = TS_NULL_MLOC;
+ int cache_lookup;
if (TS_SUCCESS == TSHttpTxnServerRespGet(txnp, &resp_buf, &resp_loc)) {
TSHttpStatus const status = TSHttpHdrStatusGet(resp_buf, resp_loc);
@@ -433,6 +451,15 @@ handle_server_read_response(TSHttpTxn txnp, txndata *const txn_state)
DEBUG_LOG("Allowing object to be cached.");
}
}
+
+ // slice requesting cache lookup status and cacheability (only on miss or validation)
+ if ((txn_state->origin_status == TS_HTTP_STATUS_PARTIAL_CONTENT || txn_state->origin_status == TS_HTTP_STATUS_NOT_MODIFIED) &&
+ txn_state->slice_request && TSHttpTxnIsCacheable(txnp, nullptr, resp_buf) &&
+ TSHttpTxnCacheLookupStatusGet(txnp, &cache_lookup) == TS_SUCCESS &&
+ (cache_lookup == TS_CACHE_LOOKUP_MISS || cache_lookup == TS_CACHE_LOOKUP_HIT_STALE)) {
+ txn_state->slice_response = true;
+ }
+
TSHandleMLocRelease(resp_buf, TS_NULL_MLOC, resp_loc);
}
}
diff --git a/plugins/experimental/slice/Data.h b/plugins/experimental/slice/Data.h
index 9cfbb2f7e..8e654a69b 100644
--- a/plugins/experimental/slice/Data.h
+++ b/plugins/experimental/slice/Data.h
@@ -93,7 +93,7 @@ struct Data {
Stage m_upstream;
Stage m_dnstream;
- std::unordered_map<int, bool> m_fetchstates;
+ bool m_prefetchable{false};
HdrMgr m_req_hdrmgr; // manager for server request
HdrMgr m_resp_hdrmgr; // manager for client response
diff --git a/plugins/experimental/slice/HttpHeader.h b/plugins/experimental/slice/HttpHeader.h
index 15a1b158e..81f1817fb 100644
--- a/plugins/experimental/slice/HttpHeader.h
+++ b/plugins/experimental/slice/HttpHeader.h
@@ -36,6 +36,9 @@
#include <string>
+constexpr std::string_view SLICE_CRR_HEADER = {"Slice-Crr-Status"};
+constexpr std::string_view SLICE_CRR_VAL = "1";
+
/**
Designed to be a cheap throwaway struct which allows a
consumer to make various calls to manipulate headers.
diff --git a/plugins/experimental/slice/prefetch.cc b/plugins/experimental/slice/prefetch.cc
index 2325db77f..a83d25a63 100644
--- a/plugins/experimental/slice/prefetch.cc
+++ b/plugins/experimental/slice/prefetch.cc
@@ -43,13 +43,13 @@ BgBlockFetch::schedule(Data *const data, int blocknum)
bool
BgBlockFetch::fetch(Data *const data)
{
- if (_bg_stream.m_read.isOpen()) {
+ if (m_stream.m_read.isOpen()) {
// should never happen since the connection was just initialized
ERROR_LOG("Background block request already in flight!");
return false;
}
- int64_t const blockbeg = (data->m_config->m_blockbytes * _blocknum);
+ int64_t const blockbeg = (data->m_config->m_blockbytes * m_blocknum);
Range blockbe(blockbeg, blockbeg + data->m_config->m_blockbytes);
char rangestr[1024];
@@ -69,11 +69,11 @@ BgBlockFetch::fetch(Data *const data)
ERROR_LOG("Error trying to set range request header %s", rangestr);
return false;
}
- TSAssert(nullptr == _cont);
+ TSAssert(nullptr == m_cont);
// Setup the continuation
- _cont = TSContCreate(handler, TSMutexCreate());
- TSContDataSet(_cont, static_cast<void *>(this));
+ m_cont = TSContCreate(handler, TSMutexCreate());
+ TSContDataSet(m_cont, static_cast<void *>(this));
// create virtual connection back into ATS
TSHttpConnectOptions options = TSHttpConnectOptionsGet(TS_CONNECT_PLUGIN);
@@ -88,16 +88,17 @@ BgBlockFetch::fetch(Data *const data)
int const hlen = TSHttpHdrLengthGet(header.m_buffer, header.m_lochdr);
// set up connection with the HttpConnect server
- _bg_stream.setupConnection(upvc);
- _bg_stream.setupVioWrite(_cont, hlen);
- TSHttpHdrPrint(header.m_buffer, header.m_lochdr, _bg_stream.m_write.m_iobuf);
+ m_stream.setupConnection(upvc);
+ m_stream.setupVioWrite(m_cont, hlen);
+ TSHttpHdrPrint(header.m_buffer, header.m_lochdr, m_stream.m_write.m_iobuf);
if (TSIsDebugTagSet(PLUGIN_NAME)) {
std::string const headerstr(header.toString());
DEBUG_LOG("Headers\n%s", headerstr.c_str());
}
+ // ensure blocks are pulled through to cache
+ m_stream.setupVioRead(m_cont, INT64_MAX);
- data->m_fetchstates[_blocknum] = true;
return true;
}
@@ -113,22 +114,37 @@ BgBlockFetch::handler(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */
switch (event) {
case TS_EVENT_VCONN_WRITE_COMPLETE:
- TSVConnShutdown(bg->_bg_stream.m_vc, 0, 1);
- bg->_bg_stream.close();
- delete bg;
+ TSVConnShutdown(bg->m_stream.m_vc, 0, 1);
break;
- default:
- if (event == TS_EVENT_VCONN_INACTIVITY_TIMEOUT) {
- DEBUG_LOG("encountered Inactivity Timeout");
- TSVConnAbort(bg->_bg_stream.m_vc, TS_VC_CLOSE_ABORT);
- } else {
- TSVConnClose(bg->_bg_stream.m_vc);
+ case TS_EVENT_VCONN_READ_READY: {
+ TSIOBufferReader const reader = bg->m_stream.m_read.m_reader;
+ if (nullptr != reader) {
+ int64_t const avail = TSIOBufferReaderAvail(reader);
+ TSIOBufferReaderConsume(reader, avail);
+ TSVIO const rvio = bg->m_stream.m_read.m_vio;
+ TSVIONDoneSet(rvio, TSVIONDoneGet(rvio) + avail);
+ TSVIOReenable(rvio);
}
- bg->_bg_stream.abort();
+ } break;
+ case TS_EVENT_NET_ACCEPT_FAILED:
+ case TS_EVENT_VCONN_INACTIVITY_TIMEOUT:
+ case TS_EVENT_VCONN_ACTIVE_TIMEOUT:
+ case TS_EVENT_ERROR:
+ bg->m_stream.abort();
+ TSContDataSet(contp, nullptr);
+ delete bg;
+ TSContDestroy(contp);
+ break;
+ case TS_EVENT_VCONN_READ_COMPLETE:
+ case TS_EVENT_VCONN_EOS:
+ bg->m_stream.close();
TSContDataSet(contp, nullptr);
delete bg;
TSContDestroy(contp);
break;
+ default:
+ DEBUG_LOG("Unhandled bg fetch event:%s (%d)", TSHttpEventNameLookup(event), event);
+ break;
}
return 0;
}
diff --git a/plugins/experimental/slice/prefetch.h b/plugins/experimental/slice/prefetch.h
index e04376bac..e5d1edfc2 100644
--- a/plugins/experimental/slice/prefetch.h
+++ b/plugins/experimental/slice/prefetch.h
@@ -35,22 +35,13 @@
struct BgBlockFetch {
static bool schedule(Data *const data, int blocknum);
- explicit BgBlockFetch(int blocknum) : _blocknum(blocknum) {}
+ explicit BgBlockFetch(int blocknum) : m_blocknum(blocknum) {}
bool fetch(Data *const data);
static int handler(TSCont contp, TSEvent event, void * /* edata ATS_UNUSED */);
/* This is for the actual background fetch / NetVC */
- Stage _bg_stream;
-
- int _blocknum;
- TSCont _cont = nullptr;
-
- ~BgBlockFetch()
- {
- if (nullptr != _cont) {
- TSContDestroy(_cont);
- _cont = nullptr;
- }
- }
+ Stage m_stream;
+ int m_blocknum;
+ TSCont m_cont = nullptr;
};
\ No newline at end of file
diff --git a/plugins/experimental/slice/server.cc b/plugins/experimental/slice/server.cc
index ddf0cc9ad..a25376bc9 100644
--- a/plugins/experimental/slice/server.cc
+++ b/plugins/experimental/slice/server.cc
@@ -20,6 +20,7 @@
#include "Config.h"
#include "ContentRange.h"
+#include "HttpHeader.h"
#include "response.h"
#include "transfer.h"
#include "util.h"
@@ -217,6 +218,10 @@ handleFirstServerHeader(Data *const data, TSCont const contp)
data->m_bytessent = hbytes;
TSVIOReenable(output_vio);
+ if (data->m_config->m_prefetchcount > 0 && header.hasKey(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size())) {
+ data->m_prefetchable = true;
+ }
+
return HeaderState::Good;
}
diff --git a/plugins/experimental/slice/util.cc b/plugins/experimental/slice/util.cc
index 7e4bc1148..f9c74ed1a 100644
--- a/plugins/experimental/slice/util.cc
+++ b/plugins/experimental/slice/util.cc
@@ -18,6 +18,7 @@
#include "util.h"
#include "prefetch.h"
+#include "HttpHeader.h"
#include "Config.h"
#include "Data.h"
@@ -86,6 +87,11 @@ request_block(TSCont contp, Data *const data)
return false;
}
+ header.removeKey(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size());
+ if (data->m_blocknum == 0 && data->m_config->m_prefetchcount > 0) {
+ header.setKeyVal(SLICE_CRR_HEADER.data(), SLICE_CRR_HEADER.size(), SLICE_CRR_VAL.data(), SLICE_CRR_VAL.size());
+ }
+
// create virtual connection back into ATS
TSHttpConnectOptions options = TSHttpConnectOptionsGet(TS_CONNECT_PLUGIN);
options.addr = reinterpret_cast<sockaddr *>(&data->m_client_ip);
@@ -112,16 +118,19 @@ request_block(TSCont contp, Data *const data)
}
// if prefetch config set, schedule next block requests in background
- for (int i = 0; i < data->m_config->m_prefetchcount; i++) {
- int nextblocknum = data->m_blocknum + i + 1;
- if (data->m_req_range.blockIsInside(data->m_config->m_blockbytes, nextblocknum) && !data->m_fetchstates[nextblocknum]) {
- if (BgBlockFetch::schedule(data, nextblocknum)) {
- DEBUG_LOG("Background fetch requested");
- } else {
- DEBUG_LOG("Background fetch not requested");
+ if (data->m_prefetchable && data->m_config->m_prefetchcount > 0) {
+ int nextblocknum = 2;
+ if (data->m_blocknum > 1) {
+ nextblocknum = data->m_blocknum + data->m_config->m_prefetchcount;
+ }
+ for (int i = nextblocknum; i <= data->m_blocknum + data->m_config->m_prefetchcount; i++) {
+ if (data->m_req_range.blockIsInside(data->m_config->m_blockbytes, i)) {
+ if (BgBlockFetch::schedule(data, i)) {
+ DEBUG_LOG("Background fetch requested");
+ } else {
+ DEBUG_LOG("Background fetch not requested");
+ }
}
- } else {
- break;
}
}
// get ready for data back from the server
diff --git a/tests/gold_tests/pluginTest/slice/gold/slice_prefetch.gold b/tests/gold_tests/pluginTest/slice/gold/slice_prefetch.gold
new file mode 100644
index 000000000..1a82ca139
--- /dev/null
+++ b/tests/gold_tests/pluginTest/slice/gold/slice_prefetch.gold
@@ -0,0 +1,27 @@
+bytes 0-6/18 miss
+bytes ``/18 miss
+bytes ``/18 miss
+bytes 14-17/18 hit-fresh
+- miss, none
+bytes 0-6/18 hit-fresh
+bytes 7-13/18 hit-fresh
+bytes 14-17/18 hit-fresh
+- hit-fresh, none
+bytes 0-6/18 hit-stale
+bytes ``/18 hit-stale
+bytes ``/18 hit-stale
+bytes 14-17/18 hit-fresh
+- hit-stale, none
+bytes 0-4/18 miss
+bytes ``/18 ``
+bytes ``/18 ``
+bytes ``/18 ``
+bytes ``/18 ``
+bytes 15-17/18 hit-fresh
+bytes 0-17/18 miss, none
+bytes 0-6/18 hit-fresh
+bytes 7-13/18 hit-fresh
+bytes 14-17/18 hit-fresh
+bytes 5-16/18 hit-fresh, none
+bytes 0-6/18 hit-fresh
+*/18 hit-fresh, none
diff --git a/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py b/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py
index 5dc6aed13..4201d6873 100644
--- a/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py
+++ b/tests/gold_tests/pluginTest/slice/slice_prefetch.test.py
@@ -15,6 +15,7 @@
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
+import os
Test.Summary = '''
slice plugin prefetch feature test
@@ -27,6 +28,7 @@ slice plugin prefetch feature test
Test.SkipUnless(
Condition.PluginExists('slice.so'),
Condition.PluginExists('cache_range_requests.so'),
+ Condition.PluginExists('xdebug.so'),
)
Test.ContinueOnFail = False
@@ -52,7 +54,7 @@ request_header = {"headers":
response_header = {"headers":
"HTTP/1.1 200 OK\r\n" +
"Connection: close\r\n" +
- "Cache-Control: public, max-age=500\r\n" +
+ "Cache-Control: public, max-age=5\r\n" +
"\r\n",
"timestamp": "1469733493.993",
"body": body,
@@ -79,7 +81,7 @@ for block_bytes in [block_bytes_1, block_bytes_2]:
resp_header = {"headers":
"HTTP/1.1 206 Partial Content\r\n" +
"Accept-Ranges: bytes\r\n" +
- "Cache-Control: public, max-age=500\r\n" +
+ "Cache-Control: public, max-age=5\r\n" +
f"Content-Range: bytes {b0}-{b1}/{bodylen}\r\n" +
"Connection: close\r\n" +
"\r\n",
@@ -88,91 +90,103 @@ for block_bytes in [block_bytes_1, block_bytes_2]:
}
server.addResponse("sessionlog.json", req_header, resp_header)
-curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x http://127.0.0.1:{}'.format(ts.Variables.port)
+curl_and_args = 'curl -s -D /dev/stdout -o /dev/stderr -x http://127.0.0.1:{} -H "x-debug: x-cache"'.format(ts.Variables.port)
ts.Disk.remap_config.AddLines([
- f'map http://sliceprefetch1bytes1/ http://127.0.0.1:{server.Variables.Port}' +
- f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_1} @pparam=--prefetch-count=1' +
+ f'map http://sliceprefetchbytes1/ http://127.0.0.1:{server.Variables.Port}' +
+ f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_1} @pparam=--prefetch-count=1 \\' +
' @plugin=cache_range_requests.so',
- f'map http://sliceprefetch2bytes1/ http://127.0.0.1:{server.Variables.Port}' +
- f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_1} @pparam=--prefetch-count=2' +
- ' @plugin=cache_range_requests.so',
- f'map http://sliceprefetch1bytes2/ http://127.0.0.1:{server.Variables.Port}' +
- f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_2} @pparam=--prefetch-count=1' +
- ' @plugin=cache_range_requests.so',
- f'map http://sliceprefetch2bytes2/ http://127.0.0.1:{server.Variables.Port}' +
- f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_2} @pparam=--prefetch-count=2' +
+ f'map http://sliceprefetchbytes2/ http://127.0.0.1:{server.Variables.Port}' +
+ f' @plugin=slice.so @pparam=--blockbytes-test={block_bytes_2} @pparam=--prefetch-count=3 \\' +
' @plugin=cache_range_requests.so',
])
+ts.Disk.plugin_config.AddLine('xdebug.so')
+ts.Disk.logging_yaml.AddLines([
+ 'logging:',
+ ' formats:',
+ ' - name: cache',
+ ' format: "%<{Content-Range}psh> %<{X-Cache}psh>"',
+ ' logs:',
+ ' - filename: cache',
+ ' format: cache',
+ ' mode: ascii',
+])
+
ts.Disk.records_config.update({
'proxy.config.diags.debug.enabled': 1,
- 'proxy.config.diags.debug.tags': 'slice|cache_range_requests|pvc',
+ 'proxy.config.diags.debug.tags': 'slice|cache_range_requests|xdebug',
})
-# 0 Test - Full object slice with only next block prefetched in background, block bytes= 7
-tr = Test.AddTestRun("Full object slice with only next block prefetched in background, block bytes= 7")
+# 0 Test - Full object slice (miss) with only block 14-20 prefetched in background, block bytes= 7
+tr = Test.AddTestRun("Full object slice: first block is miss, only block 14-20 prefetched")
ps = tr.Processes.Default
ps.StartBefore(server, ready=When.PortOpen(server.Variables.Port))
ps.StartBefore(Test.Processes.ts)
-ps.Command = curl_and_args + ' http://sliceprefetch1bytes1/path'
+ps.Command = curl_and_args + ' http://sliceprefetchbytes1/path'
ps.ReturnCode = 0
ps.Streams.stderr = "gold/slice_200.stderr.gold"
ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response")
+ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: miss", "expected cache miss")
tr.StillRunningAfter = ts
-# 1 Test - Full object slice with nest 2 blocks prefetched in background, block bytes= 7
-tr = Test.AddTestRun("Test - Full object slice with nest 2 blocks prefetched in background, block bytes= 7")
+# 1 Test - Full object slice (hit-fresh) with no prefetched blocks, block bytes= 7
+tr = Test.AddTestRun("Full object slice: first block is hit-fresh, no blocks prefetched")
ps = tr.Processes.Default
-ps.Command = curl_and_args + ' http://sliceprefetch2bytes1/path'
+ps.Command = 'sleep 1; ' + curl_and_args + ' http://sliceprefetchbytes1/path'
ps.ReturnCode = 0
ps.Streams.stderr = "gold/slice_200.stderr.gold"
ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response")
+ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: hit-fresh", "expected cache fresh")
tr.StillRunningAfter = ts
-# 2 Test - Full object slice with only next block prefetched in background, block bytes= 5
-tr = Test.AddTestRun("Full object slice with only next block prefetched in background, block bytes= 5")
+# 2 Test - Full object slice with only next block prefetched in background, block bytes= 7
+tr = Test.AddTestRun("Full object slice: first block is hit-stale, only block 14-20 prefetched")
ps = tr.Processes.Default
-ps.Command = curl_and_args + ' http://sliceprefetch1bytes2/path'
+ps.Command = 'sleep 5; ' + curl_and_args + ' http://sliceprefetchbytes1/path'
ps.ReturnCode = 0
ps.Streams.stderr = "gold/slice_200.stderr.gold"
ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response")
+ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: hit-stale", "expected cache hit-stale")
tr.StillRunningAfter = ts
-# 3 Test - Full object slice with nest 2 blocks prefetched in background, block bytes= 5
-tr = Test.AddTestRun("Full object slice with nest 2 blocks prefetched in background, block bytes= 5")
+# 3 Test - Full object slice (miss) with only blocks 10-14, 15-19 prefetched in background, block bytes= 5
+tr = Test.AddTestRun("Full object slice: first block is miss, only blocks 10-14, 15-19 prefetched")
ps = tr.Processes.Default
-ps.Command = curl_and_args + ' http://sliceprefetch2bytes2/path'
+ps.Command = curl_and_args + ' http://sliceprefetchbytes2/path' + ' -r 0-'
ps.ReturnCode = 0
ps.Streams.stderr = "gold/slice_200.stderr.gold"
-ps.Streams.stdout.Content = Testers.ContainsExpression("200 OK", "expected 200 OK response")
-tr.StillRunningAfter = ts
-
-# 4 Test - Whole asset via range
-tr = Test.AddTestRun("Whole asset via range")
-ps = tr.Processes.Default
-ps.Command = curl_and_args + ' http://sliceprefetch1bytes1/path' + ' -r 0-'
-ps.ReturnCode = 0
-ps.Streams.stderr = "gold/slice_206.stderr.gold"
ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response")
ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 0-17/18", "mismatch byte content response")
+ps.Streams.stdout.Content += Testers.ContainsExpression("X-Cache: miss", "expected cache miss")
tr.StillRunningAfter = ts
-# 5 Test - Non aligned slice request
+# 4 Test - Non aligned slice request
tr = Test.AddTestRun("Non aligned slice request")
ps = tr.Processes.Default
-ps.Command = curl_and_args + ' http://sliceprefetch1bytes1/path' + ' -r 5-16'
+ps.Command = curl_and_args + ' http://sliceprefetchbytes1/path' + ' -r 5-16'
ps.ReturnCode = 0
ps.Streams.stderr = "gold/slice_mid.stderr.gold"
ps.Streams.stdout.Content = Testers.ContainsExpression("206 Partial Content", "expected 206 response")
ps.Streams.stdout.Content += Testers.ContainsExpression("Content-Range: bytes 5-16/18", "mismatch byte content response")
tr.StillRunningAfter = ts
-# 6 Test - special case, begin inside last slice block but outside asset len
+# 5 Test - special case, begin inside last slice block but outside asset len
tr = Test.AddTestRun("Invalid end range request, 416")
beg = len(body) + 1
end = beg + block_bytes
ps = tr.Processes.Default
-ps.Command = curl_and_args + f' http://sliceprefetch1bytes1/path -r {beg}-{end}'
+ps.Command = curl_and_args + f' http://sliceprefetchbytes1/path -r {beg}-{end}'
ps.Streams.stdout.Content = Testers.ContainsExpression("416 Requested Range Not Satisfiable", "expected 416 response")
tr.StillRunningAfter = ts
+
+# 6 Test - All requests (client & slice internal) logs to see background fetches
+cache_file = os.path.join(ts.Variables.LOGDIR, 'cache.log')
+# Wait for log file to appear, then wait one extra second to make sure TS is done writing it.
+test_run = Test.AddTestRun("Checking debug logs for background fetches")
+test_run.Processes.Default.Command = (
+ os.path.join(Test.Variables.AtsTestToolsDir, 'condwait') + ' 60 1 -f ' +
+ cache_file
+)
+ts.Disk.File(cache_file).Content = "gold/slice_prefetch.gold"
+test_run.Processes.Default.ReturnCode = 0