Page MenuHomePhabricator

Acceptably efficient AbuseFilter profiling storage backend
Closed, ResolvedPublic

Description

An opt-out had to made for the use of DBMainStash for AbuseFilter profiling keys due to the high write rate, which was causing replication lag. Batching the writes (e.g. some kind of mergeMulti will not yelp with mysql).

Perhaps we could either:
a) Stick to a non-replicated redis instance (non-shared between datacenters)
b) Likewise but with mysql
c) Use memcached and broadcast the increment operations, using pipelinine, mcrouter key coalescing (like WANCache), and the latest INCR features in the memcached protocol (will require https://gerrit.wikimedia.org/r/c/mediawiki/core/+/530019 )

Event Timeline

How about c) use memcached, but using mcrouter AllAsyncRoute instead of having MW do the pipelining? Break up the blobs, so instead of ~300 CAS merges per edit, we would have ~1200 plain increment operations. Reading only happens on a GET request of AbuseFilterViewEdit so it can just use a primary DC route in mcrouter or it can be routed to the primary DC in the CDN. If an item is lost and starts again from zero, the averages will be wrong. So put the time in the key, say rounded to 10 mins, and query the last 6 time windows, emulating the current one hour expiry time.

It depends on 1200 increment operations being sufficiently fast. I can benchmark that.

Call it mcrouter-stats and use it for anything that wants to increment counters.

Change 806975 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[operations/puppet@production] mcrouter: Add stats route for fast increment

https://gerrit.wikimedia.org/r/806975

Change 806975 merged by Tim Starling:

[operations/puppet@production] mcrouter: Add stats route for fast increment

https://gerrit.wikimedia.org/r/806975

Aaron pointed out that BagOStuff::incrWithInit() won't work with AllAsyncRoute because it always returns a "not found" response, causing BagOStuff to issue an "add" command and then another "incr".

It is possible to use a speculative "add" followed by the deprecated BagOStuff::incr(). It's also possible to do the same sequence by calling PECL memcached directly.

In the future it may be possible to use the "ma" command which can do an atomic increment-with-init operation.

I benchmarked 1000 increment operations. I didn't include the add operations since the deployed mcrouter config makes them synchronous.

$params = ['routingPrefix' => '/codfw/mw-stats/'] + $wgObjectCaches['mcrouter'];
$cache = ObjectCache::newFromParams($params);
$t = microtime(true); 
for ( $i = 0; $i < 1000; $i++ ) { 
    $cache->incr('test'); 
} 
print microtime(true) -  $t;

DC-local, there was a client-side (MW) latency of ~71ms, and tcpdump shows mcrouter cleared its queue also in 71ms. Although memcached and mcrouter were going at roughly the same speed, ack timing shows that mcrouter is not waiting for a response before sending the next command, and occasionally two commands end up in one packet.

Cross-DC, client-side latency was ~60ms, and tcpdump showed mcrouter sending large packets, finishing its conversation with memcached after 133ms. The speed was apparently constrained by TCP.

I tried to break it with a batch of 100,000 cross-DC increment operations. Client-side latency was 4.6s and the answer retrieved with get() was correct, no commands were lost. This is not exactly a production-like test since there was only one server involved, but it suggests that queue overflow is not a concern.

In summary, mcrouter does do pipelining and appears to be robust. We can expect it to do a production-like task of 1200 DC-local add/increment operations with a latency in the MW client of ~170ms and the mcrouter queue empty very shortly afterwards.

Let's look at reads. I tried getMulti() with 100 keys across DCs. The first such request took 164ms ≈ 5 RTT, presumably while mcrouter established connections to all referenced servers in parallel. A second request for the same keys while the connections were still open took 40ms. This seems tolerable for AbuseFilterViewEdit.

Implementation options for BagOStuff integration:

  1. Add an incrAsync() method to the interface which returns boolean success.
  2. In MemcachedPeclBagOStuff::doIncrWithInit(), respect $flags=WRITE_BACKGROUND. If it is set, use the async client, do add/incr, and return bool.
  3. Add a constructor parameter.

I think I prefer option 2.

Change 807512 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@master] [WIP] Stats library WRStats

https://gerrit.wikimedia.org/r/807512

Change 807663 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@master] Implement asynchronous increment in memcached BagOStuff

https://gerrit.wikimedia.org/r/807663

Change 807664 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/extensions/AbuseFilter@master] FilterProfiler: use WRStats

https://gerrit.wikimedia.org/r/807664

Change 807665 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[operations/puppet@production] mcrouter: include "add" command in mw-stats route

https://gerrit.wikimedia.org/r/807665

I did some more performance testing, focusing on MediaWiki, since that seems to be the slowest part. With a batch of 1000 on mwmaint2002, talking to mcrouter on localhost, always the same key:

TestTime (µs/call)
Memcached::increment() default options52
Memcached::increment() Memcached::OPT_NO_BLOCK52
Memcached::increment() Memcached::OPT_BUFFER_WRITES52
Memcached::increment() Memcached::OPT_NOREPLY2
ObjectCache::incr()55

I confirmed in the source that libmemcached does not respect OPT_BUFFER_WRITES when doing an increment/decrement.

When I tested locally PS3 of https://gerrit.wikimedia.org/r/c/mediawiki/core/+/807663/3 I found that WRITE_BACKGROUND increased the time for incrWithInit() on a local memcached from 20µs to 117µs, mostly because disabling OPT_NO_BLOCK causes libmemcached to unconditionally terminate the connection. See behavior.cc line 138. So every increment requires a new connection.

Judging by the source, disabling OPT_BUFFER_WRITES also terminates the connection. MemcachedPeclBagOStuff should stop trying to change these options on every call.

So I am going to update the patch to use OPT_NOREPLY. I benchmarked the new incrWithInit() locally at 4µs, and strace shows an uninterrupted stream of sendto() syscalls.

I looked at whether the mw-stats route is necessary. All tests were 1000 calls of Memcached::increment() on mwmaint2002.

TestTime (µs/call)
mcrouter mw-stats53
mcrouter mw same-DC395
mcrouter mw same-DC OPT_NOREPLY2
mcrouter mw cross-DC33550
mcrouter mw cross-DC OPT_NOREPLY2
Direct cross-DC unencrypted31708
Direct cross-DC unencrypted OPT_NOREPLY2

It would seem that the mw-stats route is unnecessary when OPT_NOREPLY is used.

WRITE_BACKGROUND is currently only used by KeyValueDependencyStore so let's test its use cases while we're at it.

$memcached = new Memcached;
$memcached->addServer( '127.0.0.1', 11213 );
// $memcached->setOption( Memcached::OPT_NOREPLY, true );

$values = [];
for ( $i = 0; $i < 1000; $i++ ) {
    $values["/codfw/mw/test/mctest:$i"] = 'sss';
}

$t = microtime( true );
$memcached->setMulti( $values, 3600 );
print "set " . ( microtime( true ) - $t ) * 1000 . "\n";

$t = microtime( true );
foreach ( $values as $key => $value ) {
    $memcached->touch( $key, 3000 );
}
print "touch " . ( microtime( true ) - $t ) * 1000 . "\n";

$t = microtime( true );
$memcached->deleteMulti( array_keys( $values ) );
print "delete " . ( microtime( true ) - $t ) * 1000 . "\n";
TestTime (µs/key)
set517
touch482
delete490
set OPT_NO_BLOCK OPT_BUFFER_WRITES20
touch OPT_NO_BLOCK OPT_BUFFER_WRITES501
delete OPT_NO_BLOCK OPT_BUFFER_WRITES19
set OPT_NOREPLY1
touch OPT_NOREPLYhangs forever
delete OPT_NOREPLY1

touch with OPT_NOREPLY is not correctly implemented. I haven't fully isolated it, but it's definitely unsafe to set the OPT_NOREPLY flag for commands that don't support a noreply option, since memcached_vdo() uses memcached_is_replying() to decide whether to expect a response, even if the noreply option was not sent. The protocol says touch noreply is supported, but libmemcached doesn't implement it. And as the benchmarks suggest, touch ignores OPT_BUFFER_WRITES.

I confirmed that add() supports noreply.

Change 807665 abandoned by Tim Starling:

[operations/puppet@production] mcrouter mw-stats: make other write commands also async

Reason:

not necessary

https://gerrit.wikimedia.org/r/807665

Change 808959 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[operations/puppet@production] Revert "mcrouter: Add stats route for fast increment"

https://gerrit.wikimedia.org/r/808959

Change 808959 merged by Tim Starling:

[operations/puppet@production] Revert "mcrouter: Add stats route for fast increment"

https://gerrit.wikimedia.org/r/808959

Change 807663 merged by jenkins-bot:

[mediawiki/core@master] objectcache: Implement asynchronous increment in memcached BagOStuff

https://gerrit.wikimedia.org/r/807663

Change 810839 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@master] Optimised SqlBagOStuff::incrWithInit with WRITE_BACKGROUND

https://gerrit.wikimedia.org/r/810839

Change 810839 merged by jenkins-bot:

[mediawiki/core@master] objectcache: Optimise SqlBagOStuff::incrWithInit with WRITE_BACKGROUND

https://gerrit.wikimedia.org/r/810839

Change 807512 merged by jenkins-bot:

[mediawiki/core@master] Introduce new WRStats library for write-read stats

https://gerrit.wikimedia.org/r/807512

Change 807664 merged by jenkins-bot:

[mediawiki/extensions/AbuseFilter@master] FilterProfiler: use WRStats

https://gerrit.wikimedia.org/r/807664

Change 811394 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[operations/mediawiki-config@master] Set wgStatsCacheType to mcrouter-primary-dc

https://gerrit.wikimedia.org/r/811394

Change 811394 merged by jenkins-bot:

[operations/mediawiki-config@master] Set wgStatsCacheType to mcrouter-primary-dc

https://gerrit.wikimedia.org/r/811394

Mentioned in SAL (#wikimedia-operations) [2022-07-06T02:30:16Z] <tstarling@deploy1002> Synchronized wmf-config/InitialiseSettings.php: T310662 g 811394 harmless prerequisite (duration: 03m 39s)

Change 811407 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/core@wmf/1.39.0-wmf.19] Introduce new WRStats library for write-read stats

https://gerrit.wikimedia.org/r/811407

I'm rolling out a cherry-pick to wmf.19 so that I can test it in production separately from the train deployment. I don't think it's necessary to also cherry-pick it to wmf.18. Testing it on the group0 wikis should be enough to de-risk the train.

If any problems develop, revert the AbuseFilter patch. The core patch should be pretty harmless.

Change 811407 merged by jenkins-bot:

[mediawiki/core@wmf/1.39.0-wmf.19] Introduce new WRStats library for write-read stats

https://gerrit.wikimedia.org/r/811407

Mentioned in SAL (#wikimedia-operations) [2022-07-06T03:17:18Z] <tstarling@deploy1002> Started scap: WRStats core prereq T310662 g811407

Mentioned in SAL (#wikimedia-operations) [2022-07-06T03:34:39Z] <tstarling@deploy1002> Finished scap: WRStats core prereq T310662 g811407 (duration: 17m 20s)

Change 811408 had a related patch set uploaded (by Tim Starling; author: Tim Starling):

[mediawiki/extensions/AbuseFilter@wmf/1.39.0-wmf.19] FilterProfiler: use WRStats

https://gerrit.wikimedia.org/r/811408

Change 811408 merged by jenkins-bot:

[mediawiki/extensions/AbuseFilter@wmf/1.39.0-wmf.19] FilterProfiler: use WRStats

https://gerrit.wikimedia.org/r/811408

Mentioned in SAL (#wikimedia-operations) [2022-07-06T04:18:46Z] <tstarling@deploy1002> Synchronized php-1.39.0-wmf.19/extensions/AbuseFilter: T310662 deployment with possible post-send error spike due to ServiceWiring/FilterProfiler interdependency (duration: 03m 33s)

tstarling claimed this task.