From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [216.205.24.124]) by sourceware.org (Postfix) with ESMTP id 2102A3848410 for ; Fri, 4 Jun 2021 12:49:57 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org 2102A3848410 Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-389-zk4g2MGyNt6l-z7ybSEg6A-1; Fri, 04 Jun 2021 08:49:55 -0400 X-MC-Unique: zk4g2MGyNt6l-z7ybSEg6A-1 Received: from smtp.corp.redhat.com (int-mx06.intmail.prod.int.phx2.redhat.com [10.5.11.16]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 1E6FE818401 for ; Fri, 4 Jun 2021 12:49:54 +0000 (UTC) Received: from redhat.com (ovpn-112-13.phx2.redhat.com [10.3.112.13]) by smtp.corp.redhat.com (Postfix) with ESMTPS id DEC685C1C5 for ; Fri, 4 Jun 2021 12:49:53 +0000 (UTC) Received: from fche by redhat.com with local (Exim 4.94.2) (envelope-from ) id 1lp9Gq-0000xV-LT for elfutils-devel@sourceware.org; Fri, 04 Jun 2021 08:49:52 -0400 Date: Fri, 4 Jun 2021 08:49:52 -0400 From: "Frank Ch. Eigler" To: elfutils-devel@sourceware.org Subject: PR27863 [PATCH] - debuginfod serialization for concurrent identical requests Message-ID: <20210604124952.GE23044@redhat.com> MIME-Version: 1.0 User-Agent: Mutt/1.12.0 (2019-05-25) X-Scanned-By: MIMEDefang 2.79 on 10.5.11.16 X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset=us-ascii Content-Disposition: inline X-Spam-Status: No, score=-11.8 required=5.0 tests=BAYES_00, DKIMWL_WL_HIGH, DKIM_SIGNED, DKIM_VALID, DKIM_VALID_AU, DKIM_VALID_EF, GIT_PATCH_0, KAM_BADIPHTTP, RCVD_IN_DNSWL_LOW, RCVD_IN_MSPIKE_H4, RCVD_IN_MSPIKE_WL, SPF_HELO_NONE, SPF_PASS, TXREP autolearn=ham autolearn_force=no version=3.4.2 X-Spam-Checker-Version: SpamAssassin 3.4.2 (2018-09-13) on server2.sourceware.org X-BeenThere: elfutils-devel@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Elfutils-devel mailing list List-Unsubscribe: , List-Archive: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 04 Jun 2021 12:50:07 -0000 Hi - After a little DoS on one of the public servers yesterday, I'm thinking this should help. Author: Frank Ch. Eigler Date: Fri Jun 4 08:40:11 2021 -0400 PR27863: debuginfod optimization for concurrent requests Sometimes, due to configuration error, mishap, or DoS misadventure, a debuginfod server may receive near-concurrent requests for the exact same data from multiple clients. In practically all cases, it is beneficial to the clients, as well as the server, to serialize these requests. This way, debuginfod does not waste CPU in repeatedly & concurrently decompressing large archives or querying upstream servers. Second and later requesters can benefit from the fdcache / client-cache and get their results, probably earlier! This patch adds an "after-you" queueing phase to servicing http-buildid requests, whereby thereads serialize themselves on each query URL being serviced at the moment. Prometheus metrics are added, and the http GET trace line is modified to print the queue+service times separately. Hand-tested on large kernel-debuginfo's, and shows host CPU refusing to multiply in the face of concurrent identical queries. The automated test tries a hundred concurrent curls, at least some of which are slow enough to trigger the "after-you" wait here. Signed-off-by: Frank Ch. Eigler diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx index e0948eaba4b1..543044c6f0ea 100644 --- a/debuginfod/debuginfod.cxx +++ b/debuginfod/debuginfod.cxx @@ -705,6 +705,54 @@ static workq scanq; // just a single one // idler: thread_main_groom() +//////////////////////////////////////////////////////////////////////// + +// Unique set is a thread-safe structure that lends 'ownership' of a value +// to a thread. Other threads requesting the same thing are made to wait. +// It's like a semaphore-on-demand. +template +class unique_set +{ +private: + set values; + mutex mtx; + condition_variable cv; +public: + unique_set() {} + ~unique_set() {} + + void acquire(const T& value) + { + unique_lock lock(mtx); + while (values.find(value) != values.end()) + cv.wait(lock); + values.insert(value); + } + + void release(const T& value) + { + unique_lock lock(mtx); + // assert (values.find(value) != values.end()); + values.erase(value); + cv.notify_all(); + } +}; + + +// This is the object that's instantiate to uniquely hold a value in a +// RAII-pattern way. +template +class unique_set_reserver +{ +private: + unique_set& please_hold; + T mine; +public: + unique_set_reserver(unique_set& t, const T& value): + please_hold(t), mine(value) { please_hold.acquire(mine); } + ~unique_set_reserver() { please_hold.release(mine); } +}; + //////////////////////////////////////////////////////////////////////// @@ -1961,6 +2009,7 @@ handler_cb (void * /*cls*/, off_t http_size = -1; struct timespec ts_start, ts_end; clock_gettime (CLOCK_MONOTONIC, &ts_start); + double afteryou = 0.0; try { @@ -1973,7 +2022,25 @@ handler_cb (void * /*cls*/, if (slash1 != string::npos && url1 == "/buildid") { + // PR27863: block this thread awhile if another thread is already busy + // fetching the exact same thing. This is better for Everyone. + // The latecomer says "... after you!" and waits. + add_metric ("thread_busy", "role", "http-buildid-after-you", 1); +#ifdef HAVE_PTHREAD_SETNAME_NP + (void) pthread_setname_np (pthread_self(), "mhd-buildid-after-you"); +#endif + struct timespec tsay_start, tsay_end; + clock_gettime (CLOCK_MONOTONIC, &tsay_start); + static unique_set busy_urls; + unique_set_reserver after_you(busy_urls, url1); + clock_gettime (CLOCK_MONOTONIC, &tsay_end); + afteryou = (tsay_end.tv_sec - tsay_start.tv_sec) + (tsay_end.tv_nsec - tsay_start.tv_nsec)/1.e9; + add_metric ("thread_busy", "role", "http-buildid-after-you", -1); + tmp_inc_metric m ("thread_busy", "role", "http-buildid"); +#ifdef HAVE_PTHREAD_SETNAME_NP + (void) pthread_setname_np (pthread_self(), "mhd-buildid"); +#endif size_t slash2 = url_copy.find('/', slash1+1); if (slash2 == string::npos) throw reportable_exception("/buildid/ webapi error, need buildid"); @@ -2036,10 +2103,12 @@ handler_cb (void * /*cls*/, clock_gettime (CLOCK_MONOTONIC, &ts_end); double deltas = (ts_end.tv_sec - ts_start.tv_sec) + (ts_end.tv_nsec - ts_start.tv_nsec)/1.e9; + // afteryou: delay waiting for other client's identical query to complete + // deltas: total latency, including afteryou waiting obatched(clog) << conninfo(connection) << ' ' << method << ' ' << url << ' ' << http_code << ' ' << http_size - << ' ' << (int)(deltas*1000) << "ms" + << ' ' << (int)(afteryou*1000) << '+' << (int)((deltas-afteryou)*1000) << "ms" << endl; // related prometheus metrics @@ -2053,6 +2122,10 @@ handler_cb (void * /*cls*/, deltas*1000); // prometheus prefers _seconds and floating point inc_metric("http_responses_duration_milliseconds_count","code",http_code_str); + add_metric("http_responses_after_you_milliseconds_sum","code",http_code_str, + afteryou*1000); + inc_metric("http_responses_after_you_milliseconds_count","code",http_code_str); + return rc; } diff --git a/tests/run-debuginfod-find.sh b/tests/run-debuginfod-find.sh index 9183cccb7201..0445bce1e765 100755 --- a/tests/run-debuginfod-find.sh +++ b/tests/run-debuginfod-find.sh @@ -580,6 +580,20 @@ testrun ${abs_top_builddir}/debuginfod/debuginfod-find debuginfo $BUILDID # Confirm that some debuginfod client pools are being used curl -s http://127.0.0.1:$PORT2/metrics | grep 'dc_pool_op.*reuse' +# Trigger a flood of requests against the same archive content file. +# Use a file that hasn't been previously extracted in to make it +# likely that even this test debuginfod will experience concurrency +# and impose some "after-you" delays. +(for i in `seq 100`; do + curl -s http://127.0.0.1:$PORT1/buildid/87c08d12c78174f1082b7c888b3238219b0eb265/executable >/dev/null & + done; + wait) +curl -s http://127.0.0.1:$PORT1/metrics | grep 'http_responses_after_you.*' +# If we could guarantee some minimum number of seconds of CPU time, we +# could assert that the after_you metrics show some nonzero amount of +# waiting. A few hundred ms is typical on this developer's workstation. + + ######################################################################## # Corrupt the sqlite database and get debuginfod to trip across its errors curl -s http://127.0.0.1:$PORT1/metrics | grep 'sqlite3.*reset'