問題描述

hugegraph-0.10.4 版本的 cassandra 后端運行 tinkerpop 的 process 測試時，有一個時而跑過時而跑不過的測試用例：ProcessBasicSuite 的 EarlyLimitStrategyProcessTest.class。

這個測試用例只有一個測試的方法，并且這個本身本身也沒有什么值得關(guān)注的點，關(guān)鍵在于這個測試用例創(chuàng)建了有 2w 多條邊，然后在清理數(shù)據(jù)，準確地說是執(zhí)行 VertexLabelRemoveCallable 異步任務(wù)時，報了 "undefined edgelabel xx" 的錯誤。詳細的堆棧信息如圖：

問題定位

Step 1

從日志可以看出，在刪除頂點（由刪除 vertexlabel 引發(fā)）時，查到了頂點關(guān)聯(lián)的邊，然后在反序列化該條邊的過程中，卻找不到這條邊對應(yīng)的 edgelabel。

要知道，清理元數(shù)據(jù)是有順序的，先清理 edgelabel，再清理 vertexlabel，最后清理 propertykey，這個大流程肯定是不會有問題的。

所以日志中已經(jīng)到了刪除 vertexlabel 的階段，所以肯定已經(jīng)先刪除過 edgelabel 了，后面報 "找不到 edgelabel" 其實是合理的。所以問題的關(guān)鍵在于：為什么能查到頂點關(guān)聯(lián)的邊。

理所當(dāng)然地，猜測是不是刪除 edgelabel 時，沒有把邊刪干凈。

Step 2

為了提升刪除效率，cassandra 的刪除 edgelabel（觸發(fā)刪除邊數(shù)據(jù)）是下沉到 backend 層的，代碼片段為：

protected void deleteEdgesByLabel(CassandraSessionPool.Session session,
                                          Id label) {
    // Edges in edges_in table will be deleted when direction is OUT
    if (this.direction == Directions.IN) {
        return;
    }

    final String OWNER_VERTEX = formatKey(HugeKeys.OWNER_VERTEX);
    final String OTHER_VERTEX = formatKey(HugeKeys.OTHER_VERTEX);

    // Query edges by label index
    Select select = QueryBuilder.select().from(this.labelIndexTable());
    select.where(formatEQ(HugeKeys.LABEL, label.asLong()));

    ResultSet rs;
    try {
        rs = session.execute(select);
    } catch (DriverException e) {
        throw new BackendException("Failed to query edges " +
                  "with label '%s' for deleting", e, label);
    }

    // Delete edges
    int count = 0;
    for (Iterator<Row> it = rs.iterator(); it.hasNext();) {
        Row row = it.next();
        // Delete OUT edges from edges_out table
        Object ownerVertex = row.getObject(OWNER_VERTEX);
        session.add(buildDelete(label, ownerVertex, Directions.OUT));

        // Delete IN edges from edges_in table
        Object otherVertex = row.getObject(OTHER_VERTEX);
        session.add(buildDelete(label, otherVertex, Directions.IN));

        count += 2;
        // COMMIT_DELETE_BATCH is 1000
        if (count >= COMMIT_DELETE_BATCH - 2) {
            session.commit();
            count = 0;
        }
    }
}

private Delete buildDelete(Id label, Object ownerVertex,
                           Directions direction) {
    Delete delete = QueryBuilder.delete().from(edgesTable(direction));
    delete.where(formatEQ(HugeKeys.OWNER_VERTEX, ownerVertex));
    delete.where(formatEQ(HugeKeys.DIRECTION,
                          EdgeId.directionToCode(direction)));
    delete.where(formatEQ(HugeKeys.LABEL, label.asLong()));
    return delete;
}

大致邏輯就是：根據(jù) label 從出邊表中查出所有匹配的邊，提取出該邊的 owner_vertex 和 other_vertex，分別作為出邊和入邊表的 owner_vertex，再拼上 direction 和 label 共三個字端作為條件，構(gòu)造 delete 語句刪除出邊和入邊表中符合條件的記錄。

既然是懷疑邊數(shù)據(jù)沒有刪干凈，那就在所有的刪除語句提交后再查一下邊表，看能否查到數(shù)據(jù)。具體改動是在deleteEdgesByLabel的 for 循環(huán)后面，增加一段查詢的代碼。

String select2 = "SELECT * FROM g_ie where label = 28 limit 10 allow filtering;";
ResultSet resultSet = session.execute(select2);
resultSet.forEach(row -> {
    otherVertexs.forEach(ov -> {
        System.out.println("原有頂點: " + IdUtil.readBinString(ov));
    });

    System.out.println("owner_vertex: " + Bytes.toHex(IdUtil.readBinString(row.getObject("owner_vertex")).asBytes()));
    System.out.println("other_vertex: " + Bytes.toHex(IdUtil.readBinString(row.getObject("other_vertex")).asBytes()));
});

當(dāng)運行失敗時，果然能在控制臺看到增加的打印信息，所以，邊沒有刪干凈是確定無疑的。

其實這里一開始查詢語句是SELECT * FROM g_oe的，然后怎么跑都看不到打印信息，但是分析錯誤日志始終認為就是還有殘留邊，然后改成了g_ie。

Step 3

既然是邊沒有刪干凈，第一反應(yīng)是不是刪除語句的最后一批忘了提交，觀察代碼，發(fā)現(xiàn)好像確實是有這個問題，于是在 for 循環(huán)后面增加了一個提交，代碼：

if (count > 0) {
    session.commit();
}

滿心歡喜地以為找到了 bug ，運行，結(jié)果還是能查出來。還不死心，把if (count > 0)的判斷也去掉，強行提交一波。但是依然無果。

難道是 cassandra 本身的刪除有 bug ？

Step 4

本來想著下載一個新版的 cassandra 試試，無奈網(wǎng)速太慢，只得一邊下載，一邊繼續(xù)調(diào)試。

為了驗證是不是 cassandra 自己的 bug，我決定把所有的刪除語句全打印出來，看最后殘留的邊到底有沒有構(gòu)造過對應(yīng)的刪除語句。

我在session.commit()里面加上了打印語句，代碼：

this.batch.getStatements().forEach(statement -> {
    System.out.println("\t" + statement);
});

這么加的時候其實感覺很虛的，因為總共有幾萬條邊，本身又還有其他的打印信息，混在一個眼睛都花了。但是沒辦法，已經(jīng)不知道咋辦了，只能試一試。

誰知這一試還真的有發(fā)現(xiàn)，結(jié)果就不貼了，很長，反正能看到殘留的邊確實沒有構(gòu)造過刪除語句，也就是說，那條邊就是沒有被刪除過，這說明還是我們自己的問題，跟 cassandra 無關(guān)。

Step 5

這里又立馬有了一個猜測，是不是在刪除的過程中又有別的線程插入了新的入邊，或者是一開始入邊表就比出邊表有多的記錄。

分別驗證。

首先把TaskManager中的線程數(shù)調(diào)整為 1，然后又在session.commit()里面加上了打印線程的語句，代碼：

System.out.println("線程：" + Thread.currentThread().getName() + "\t批的大?。? + this.batch.size());

運行日志：

線程task-worker-1 批的大小: 1000
    第一條語句：DELETE FROM g_oe WHERE OWNER_VERTEX=0x91323533383336303032333837323936323539 AND DIRECTION=-126 AND LABEL=28 AND SORT_VALUES='' AND OTHER_VERTEX=0x91323533383336303032303937383839323830;
    最后一條語句：DELETE FROM g_ie WHERE OWNER_VERTEX=0x91323533383336303032323738323434333533 AND DIRECTION=-116 AND LABEL=28 AND SORT_VALUES='' AND OTHER_VERTEX=0x91323533383336303032323332313037303038;
線程task-worker-1 批的大小: 1000
    ...
線程task-worker-1 批的大小: 1000
    ...
線程task-worker-1 批的大小: 1000
    ...
線程task-worker-1 批的大小: 94

能看到，從開始刪除之后，task-worker-1 的語句都是連續(xù)的，且語句全都是 DELETE，沒有 INSERT。所以，不是別的線程插入了新的記錄。

Step 6

再看看是不是一開始入邊表就多插入了一些記錄。

那就在刪除之前查一下出邊表和入邊表的記錄數(shù)，看是否一致，在deleteEdgesByLabel的入口處添加代碼：

// 出邊和入邊表的記錄數(shù)
String countQuery = "select count(*) from g_oe where label = " + label.asLong() + ";";
ResultSet rs = session.execute(countQuery);
System.out.println(">> 出邊記錄數(shù)：" + rs.one().getObject(0));

countQuery = "select count(*) from g_ie where label = " + label.asLong() + ";";
rs = session.execute(countQuery);
System.out.println("<< 入邊記錄數(shù)：" + rs.one().getObject(0));

運行日志：

>> 出邊記錄數(shù)：7047
<< 入邊記錄數(shù)：7047

天啊，出邊和入邊數(shù)也是一樣的。那還能是哪兒的問題呢？

Step 7

貌似只能是迭代的問題了，那就在加上一個迭代次數(shù)的打印吧，代碼：

int iterCount = 0;
for () {
    iterCount++;
}
System.out.println("查詢label的迭代次數(shù): " + iterCount);

運行日志：

查詢label的迭代次數(shù): 7018

What？怎么迭代次數(shù)和邊記錄數(shù)不一樣，難道是一邊查一邊刪讓 cassandra 的查詢跳躍了？不太可能吧，cassandra 連這都不能保證？

Step 8

這時，ZM 突然想到：是不是刪除的比查詢到的多。

猜測是這樣：

如果某個點有很多出邊，那出邊表和入邊表的數(shù)據(jù)類似于：

出邊表：

A -> B
...
A -> C

入邊表：

...
B -> A
...
C -> A
...

cassandra 的查詢是一批一批獲取的，因為那么多的數(shù)據(jù)肯定不能一次性全取完。如果這一次查詢從出邊表中獲取到了 A -> B，但是沒獲取到 A -> C，那構(gòu)造出的刪除語句為：

出邊：

DELETE FROM g_oe WHERE owner_vertex = A and direction = out and label = 28;

入邊：

DELETE FROM g_ie WHERE owner_vertex = B and direction = in and label = 28;

但是 cassandra 的刪除卻能作用于所有owner_vertex = A的記錄上，這就刪除了出邊表中所有的A -> x（包含A -> C）的記錄，而入邊表刪除了形如B -> x的記錄。

然后 cassandra 獲取從出邊表獲取下一批的時候，已經(jīng)讀不到A -> C了，自然也沒辦法從入邊表中刪除形如C -> x的記錄，所以入邊表就有了殘留記錄。

經(jīng)過驗證，確實就是這個原因。

重現(xiàn)方式

重現(xiàn)這個問題的關(guān)鍵在于構(gòu)造出“超級點”，讓這個超級點的出邊個數(shù)大于 cassandra 的查詢 fetch_size。

解決方案

1. 修改刪除語句的構(gòu)造方式，將刪除范圍限定的小一點；
2. 讓出邊表和入邊表各自刪除各自的。