search

RedisGraph / RedisGraph

A graph database as a Redis module
https://redis.io/docs/stack/graph/
Other
2.01k stars 229 forks source link

Varying results on match, merge of a server lock-up and seemingly off query stats on a second execution of query #1113

Open joshdurbin opened 4 years ago

joshdurbin commented 4 years ago

Howdy!

I'm running into an issue, experiencing a lockup, or a freeze, rather than a crash in a certain scenario. Each test is done with a fresh instance -- no data.

The crash involves re-executing a query where the first attempt at the query returns the error (error) Type mismatch: expected a map but was Unknown. The query is a multi match, merge where the merge itself creates edges between existing nodes, creates a new node or nodes, and edges.

The dataset to reproduce is small and relatively simple and is show via a redis client instance in monitor mode.

Pass to crash

Monitor for index creation, person and product node creation

127.0.0.1:6379> monitor
OK
1591160369.694658 [0 172.17.0.1:48566] "graph.QUERY" "prodrec" "create index on :person(id)" "--COMPACT"
1591160369.700354 [0 172.17.0.1:48566] "graph.QUERY" "prodrec" "create index on :product(id)" "--COMPACT"
1591160369.702398 [0 172.17.0.1:48566] "graph.QUERY" "prodrec" "create index on :order(id)" "--COMPACT"
1591160369.995219 [0 172.17.0.1:48566] "graph.QUERY" "prodrec" "CREATE (:person {id: 5, name:\"Alexandra Lakin\",age:30,address:\"Suite 076 850 Roob Crossroad, Bernhardtown, MD 95628-3856\",memberSince:1042667969})" "--COMPACT"
1591160369.996059 [0 172.17.0.1:48582] "graph.QUERY" "prodrec" "CREATE (:person {id: 3, name:\"Thanh Ondricka\",age:19,address:\"5059 Del Springs, Lake Mariselaville, KS 81887\",memberSince:1172181569})" "--COMPACT"
1591160369.996567 [0 172.17.0.1:48578] "graph.QUERY" "prodrec" "CREATE (:person {id: 4, name:\"Deshawn Ledner\",age:13,address:\"Apt. 788 55129 Aufderhar Mountain, Lake Faustino, VA 82614\",memberSince:974411969})" "--COMPACT"
1591160369.997135 [0 172.17.0.1:48580] "graph.QUERY" "prodrec" "CREATE (:person {id: 0, name:\"Weldon Hyatt\",age:95,address:\"053 Wallace Creek, Debrahland, MN 46503\",memberSince:1578434369})" "--COMPACT"
1591160369.997232 [0 172.17.0.1:48584] "graph.QUERY" "prodrec" "CREATE (:person {id: 1, name:\"Gene Welch\",age:26,address:\"Apt. 945 31635 Turner Mill, Stoltenbergside, VT 10337\",memberSince:1440194369})" "--COMPACT"
1591160369.997324 [0 172.17.0.1:48586] "graph.QUERY" "prodrec" "CREATE (:person {id: 2, name:\"Roman Rice\",age:37,address:\"7881 Gerhold Flats, West Brendon, VA 60985\",memberSince:1531432769})" "--COMPACT"
1591160370.006133 [0 172.17.0.1:48586] "graph.QUERY" "prodrec" "CREATE (:person {id: 6, name:\"Necole Schaden\",age:11,address:\"664 Lehner Village, West Florinehaven, AZ 56455-4965\",memberSince:1444082369}),(:person {id: 7, name:\"Lindsay Blanda\",age:34,address:\"Apt. 471 2525 Schuppe Islands, Jerdeburgh, LA 00168-6905\",memberSince:1152309569}),(:person {id: 8, name:\"Guy Kshlerin\",age:34,address:\"Suite 781 701 Rowe Keys, Schadenmouth, AL 78035-4942\",memberSince:1408831169}),(:person {id: 9, name:\"Margarete Gibson\",age:38,address:\"Suite 838 4806 Gino Walk, East Jimmie, OH 37693\",memberSince:1045346369})" "--COMPACT"
1591160370.098444 [0 172.17.0.1:48586] "graph.QUERY" "prodrec" "CREATE (:product {id: 0,name:\"Fantastic Leather Pants\",manufacturer:\"Legros Inc\",msrp:'538.75'})" "--COMPACT"
1591160370.098507 [0 172.17.0.1:48566] "graph.QUERY" "prodrec" "CREATE (:product {id: 1,name:\"Ergonomic Wool Hat\",manufacturer:\"Blick-Kuhn\",msrp:'47.2'})" "--COMPACT"
1591160370.099368 [0 172.17.0.1:48584] "graph.QUERY" "prodrec" "CREATE (:product {id: 2,name:\"Fantastic Paper Computer\",manufacturer:\"Collins-Morar\",msrp:'981.75'})" "--COMPACT"
1591160370.099436 [0 172.17.0.1:48580] "graph.QUERY" "prodrec" "CREATE (:product {id: 3,name:\"Sleek Cotton Wallet\",manufacturer:\"Willms-Haley\",msrp:'28.62'})" "--COMPACT"
1591160370.100247 [0 172.17.0.1:48578] "graph.QUERY" "prodrec" "CREATE (:product {id: 4,name:\"Ergonomic Rubber Pants\",manufacturer:\"Runolfsdottir-Kunze\",msrp:'200.48'})" "--COMPACT"
1591160370.100341 [0 172.17.0.1:48582] "graph.QUERY" "prodrec" "CREATE (:product {id: 5,name:\"Awesome Aluminum Bottle\",manufacturer:\"Ryan-Douglas\",msrp:'745.93'})" "--COMPACT"
1591160370.101954 [0 172.17.0.1:48584] "graph.QUERY" "prodrec" "CREATE (:product {id: 8,name:\"Gorgeous Granite Gloves\",manufacturer:\"Doyle-Witting\",msrp:'524.72'})" "--COMPACT"
1591160370.102025 [0 172.17.0.1:48586] "graph.QUERY" "prodrec" "CREATE (:product {id: 9,name:\"Small Paper Lamp\",manufacturer:\"Rodriguez and Sons\",msrp:'95.92'})" "--COMPACT"
1591160370.102093 [0 172.17.0.1:48566] "graph.QUERY" "prodrec" "CREATE (:product {id: 6,name:\"Durable Wool Keyboard\",manufacturer:\"Mosciski-Schulist\",msrp:'207.96'}),(:product {id: 7,name:\"Fantastic Leather Clock\",manufacturer:\"Kiehn-Rodriguez\",msrp:'952.25'})" "--COMPACT"

Query that results in Type mismatch

In another client the request is made to execute the multi-match, merge that results in an error:

127.0.0.1:6379> graph.query prodrec "MATCH (p8:person {id: 8}), (prd6:product {id: 6}), (prd2:product {id: 2}), (prd3:product {id: 3}), (prd7:product {id: 7}), (prd4:product {id: 4}), (prd0:product {id: 0}), (prd5:product {id: 5}) MERGE (p8)-[:view {time: 1510534349}]->(prd6) MERGE (p8)-[:view {time: 1493555849}]->(prd2) MERGE (p8)-[:addtocart {time: 1423488329}]->(prd3) MERGE (p8)-[:addtocart {time: 1430040509}]->(prd7) MERGE (p8)-[:view {time: 1412499989}]->(prd4) MERGE (p8)-[:addtocart {time: 1449420509}]->(prd0) MERGE (p8)-[:view {time: 1557247769}]->(prd5) MERGE (p8)-[:addtocart {time: 1423488329}]->(prd3) MERGE (p8)-[:addtocart {time: 1430040509}]->(prd7) MERGE (p8)-[:addtocart {time: 1449420509}]->(prd0) MERGE (o8:order {id: 8,subTotal:980.87,tax:107.8,shipping:45.08,total:1133.75}) MERGE (o9:order {id: 9,subTotal:538.75,tax:59.4,shipping:31.32,total:629.47}) MERGE (p8)-[:transact {time: 1430040509}]->(o8) MERGE (o8)-[:contain]->(prd3) MERGE (o8)-[:contain]->(prd7) MERGE (p8)-[:transact {time: 1449420509}]->(o9) MERGE (o9)-[:contain]->(prd0) MERGE (p8)-[:rating {time: 1449420509, rating: 8}]->(prd0)"
1) (error) Type mismatch: expected a map but was Unknown

When this query is executed the Redis Server log reports:

1:M 03 Jun 2020 05:00:11.163 # <graph> RedisGraph used forced unlocking commit flow for the query MATCH (p8:person {id: 8}), (prd6:product {id: 6}), (prd2:product {id: 2}), (prd3:product {id: 3}), (prd7:product {id: 7}), (prd4:product {id: 4}), (prd0:product {id: 0}), (prd5:product {id: 5}) MERGE (p8)-[:view {time: 1510534349}]->(prd6) MERGE (p8)-[:view {time: 1493555849}]->(prd2) MERGE (p8)-[:addtocart {time: 1423488329}]->(prd3) MERGE (p8)-[:addtocart {time: 1430040509}]->(prd7) MERGE (p8)-[:view {time: 1412499989}]->(prd4) MERGE (p8)-[:addtocart {time: 1449420509}]->(prd0) MERGE (p8)-[:view {time: 1557247769}]->(prd5) MERGE (p8)-[:addtocart {time: 1423488329}]->(prd3) MERGE (p8)-[:addtocart {time: 1430040509}]->(prd7) MERGE (p8)-[:addtocart {time: 1449420509}]->(prd0) MERGE (o8:order {id: 8,subTotal:980.87,tax:107.8,shipping:45.08,total:1133.75}) MERGE (o9:order {id: 9,subTotal:538.75,tax:59.4,shipping:31.32,total:629.47}) MERGE (p8)-[:transact {time: 1430040509}]->(o8) MERGE (o8)-[:contain]->(prd3) MERGE (o8)-[:contain]->(prd7) MERGE

The issue is present for shorter queries too, that aren't truncated, but share the same "components", just a fewer of them.

At this point the server is still and responding. Re-executing the query, however, locks the Redis instance.

Re-run query to lock server

127.0.0.1:6379> graph.query prodrec "MATCH (p8:person {id: 8}), (prd6:product {id: 6}), (prd2:product {id: 2}), (prd3:product {id: 3}), (prd7:product {id: 7}), (prd4:product {id: 4}), (prd0:product {id: 0}), (prd5:product {id: 5}) MERGE (p8)-[:view {time: 1510534349}]->(prd6) MERGE (p8)-[:view {time: 1493555849}]->(prd2) MERGE (p8)-[:addtocart {time: 1423488329}]->(prd3) MERGE (p8)-[:addtocart {time: 1430040509}]->(prd7) MERGE (p8)-[:view {time: 1412499989}]->(prd4) MERGE (p8)-[:addtocart {time: 1449420509}]->(prd0) MERGE (p8)-[:view {time: 1557247769}]->(prd5) MERGE (p8)-[:addtocart {time: 1423488329}]->(prd3) MERGE (p8)-[:addtocart {time: 1430040509}]->(prd7) MERGE (p8)-[:addtocart {time: 1449420509}]->(prd0) MERGE (o8:order {id: 8,subTotal:980.87,tax:107.8,shipping:45.08,total:1133.75}) MERGE (o9:order {id: 9,subTotal:538.75,tax:59.4,shipping:31.32,total:629.47}) MERGE (p8)-[:transact {time: 1430040509}]->(o8) MERGE (o8)-[:contain]->(prd3) MERGE (o8)-[:contain]->(prd7) MERGE (p8)-[:transact {time: 1449420509}]->(o9) MERGE (o9)-[:contain]->(prd0) MERGE (p8)-[:rating {time: 1449420509, rating: 8}]->(prd0)"

At this point Redis never returns and the server is in a forever blocking state.

A small example, though, that results in a different outcome is the following:

Crashless pass

In this pass, again, the server is stopped and restated. No data is shared.

Monitor for index creation, person and product node creation

127.0.0.1:6379> monitor
OK
1591161315.157837 [0 172.17.0.1:48626] "graph.QUERY" "prodrec" "create index on :person(id)" "--COMPACT"
1591161315.163467 [0 172.17.0.1:48626] "graph.QUERY" "prodrec" "create index on :product(id)" "--COMPACT"
1591161315.165327 [0 172.17.0.1:48626] "graph.QUERY" "prodrec" "create index on :order(id)" "--COMPACT"
1591161315.477554 [0 172.17.0.1:48626] "graph.QUERY" "prodrec" "CREATE (:person {id: 0, name:\"Freeman Hoppe\",age:28,address:\"1278 Marks Rapids, Hyattview, WV 47504\",memberSince:1213308915})" "--COMPACT"
1591161315.478618 [0 172.17.0.1:48642] "graph.QUERY" "prodrec" "CREATE (:person {id: 4, name:\"Hailey Schmitt\",age:58,address:\"658 Zina Park, Jaysonborough, TN 07207\",memberSince:1331936115})" "--COMPACT"
1591161315.478732 [0 172.17.0.1:48638] "graph.QUERY" "prodrec" "CREATE (:person {id: 3, name:\"Lilli Senger\",age:37,address:\"Apt. 912 980 Beier Trace, Buenashire, MI 46392-3881\",memberSince:1528668915})" "--COMPACT"
1591161315.478837 [0 172.17.0.1:48644] "graph.QUERY" "prodrec" "CREATE (:person {id: 2, name:\"Tony Hodkiewicz\",age:57,address:\"2356 Porfirio Shore, Fritzland, PA 08495-2240\",memberSince:1501452915})" "--COMPACT"
1591161315.479088 [0 172.17.0.1:48640] "graph.QUERY" "prodrec" "CREATE (:person {id: 1, name:\"Gavin Dicki\",age:68,address:\"3492 Schamberger Lane, Botsfordborough, DE 86335\",memberSince:1151792115})" "--COMPACT"
1591161315.569199 [0 172.17.0.1:48640] "graph.QUERY" "prodrec" "CREATE (:product {id: 0,name:\"Awesome Linen Wallet\",manufacturer:\"Herman-Reilly\",msrp:'173.59'})" "--COMPACT"
1591161315.569501 [0 172.17.0.1:48644] "graph.QUERY" "prodrec" "CREATE (:product {id: 1,name:\"Enormous Plastic Gloves\",manufacturer:\"Hintz, Kling and Klocko\",msrp:'7.26'})" "--COMPACT"
1591161315.569765 [0 172.17.0.1:48638] "graph.QUERY" "prodrec" "CREATE (:product {id: 2,name:\"Intelligent Silk Bag\",manufacturer:\"Bode, Leannon and Auer\",msrp:'475.29'})" "--COMPACT"
1591161315.572086 [0 172.17.0.1:48642] "graph.QUERY" "prodrec" "CREATE (:product {id: 3,name:\"Fantastic Granite Shoes\",manufacturer:\"Emard, Gerlach and Kuphal\",msrp:'489.75'})" "--COMPACT"
1591161315.572380 [0 172.17.0.1:48626] "graph.QUERY" "prodrec" "CREATE (:product {id: 4,name:\"Incredible Marble Computer\",manufacturer:\"Davis LLC\",msrp:'210.81'})" "--COMPACT"

Query that results in Type mismatch

127.0.0.1:6379> graph.query prodrec "MATCH (p1:person {id: 1}), (prd2:product {id: 2}), (prd1:product {id: 1}), (prd0:product {id: 0}), (prd4:product {id: 4}), (prd3:product {id: 3}) MERGE (p1)-[:view {time: 1369171755}]->(prd2) MERGE (p1)-[:view {time: 1443346815}]->(prd1) MERGE (p1)-[:view {time: 1161228015}]->(prd0) MERGE (p1)-[:addtocart {time: 1477134135}]->(prd4) MERGE (p1)-[:view {time: 1411229895}]->(prd3) MERGE (p1)-[:addtocart {time: 1477134135}]->(prd4) MERGE (o2:order {id: 2,subTotal:210.81,tax:11.13,shipping:25.2,total:247.14}) MERGE (p1)-[:transact {time: 1477134135}]->(o2) MERGE (o2)-[:contain]->(prd4) MERGE (p1)-[:rating {time: 1477134135, rating: 2}]->(prd4)"
1) (error) Type mismatch: expected a map but was Unknown

When this query is executed the Redis Server log reports:

1:M 03 Jun 2020 05:15:47.013 # <graph> RedisGraph used forced unlocking commit flow for the query MATCH (p1:person {id: 1}), (prd2:product {id: 2}), (prd1:product {id: 1}), (prd0:product {id: 0}), (prd4:product {id: 4}), (prd3:product {id: 3}) MERGE (p1)-[:view {time: 1369171755}]->(prd2) MERGE (p1)-[:view {time: 1443346815}]->(prd1) MERGE (p1)-[:view {time: 1161228015}]->(prd0) MERGE (p1)-[:addtocart {time: 1477134135}]->(prd4) MERGE (p1)-[:view {time: 1411229895}]->(prd3) MERGE (p1)-[:addtocart {time: 1477134135}]->(prd4) MERGE (o2:order {id: 2,subTotal:210.81,tax:11.13,shipping:25.2,total:247.14}) MERGE (p1)-[:transact {time: 1477134135}]->(o2) MERGE (o2)-[:contain]->(prd4) MERGE (p1)-[:rating {time: 1477134135, rating: 2}]->(prd4)

Re-run query, receive results

127.0.0.1:6379> graph.query prodrec "MATCH (p1:person {id: 1}), (prd2:product {id: 2}), (prd1:product {id: 1}), (prd0:product {id: 0}), (prd4:product {id: 4}), (prd3:product {id: 3}) MERGE (p1)-[:view {time: 1369171755}]->(prd2) MERGE (p1)-[:view {time: 1443346815}]->(prd1) MERGE (p1)-[:view {time: 1161228015}]->(prd0) MERGE (p1)-[:addtocart {time: 1477134135}]->(prd4) MERGE (p1)-[:view {time: 1411229895}]->(prd3) MERGE (p1)-[:addtocart {time: 1477134135}]->(prd4) MERGE (o2:order {id: 2,subTotal:210.81,tax:11.13,shipping:25.2,total:247.14}) MERGE (p1)-[:transact {time: 1477134135}]->(o2) MERGE (o2)-[:contain]->(prd4) MERGE (p1)-[:rating {time: 1477134135, rating: 2}]->(prd4)"
1) 1) "Nodes created: 1"
   2) "Properties set: 8"
   3) "Relationships created: 3"
   4) "Query internal execution time: 2.979400 milliseconds"

The results of this query are interesting because, from my count, the number of relationships created should be 9, which makes me think I'm doing something stupid.

Version

127.0.0.1:6379> module list
1) 1) "name"
   2) "graph"
   3) "ver"
   4) (integer) 20012
swilly22 commented 4 years ago

HI @joshdurbin Thank you for the detailed report!

I've run your queries and was able to re-produce the issue, to give some details, this locking we're experiencing has to do with the way we index our nodes. When re-running the queries (skipping index creation) I was able to execute the large MERGE query to completion.

We'll look into it and update here once a fix is available.

joshdurbin commented 4 years ago

In the meantime I can do:

MATCH (p9:person {id: 9}), (prd5:product {id: 5}), (prd6:product {id: 6}), (prd7:product {id: 7}), (prd0:product {id: 0}), (prd4:product {id: 4}), (prd2:product {id: 2}), (prd9:product {id: 9}), (prd8:product {id: 8}), (prd3:product {id: 3}), (prd1:product {id: 1}) CREATE (p9)-[:view {time: 1387897946}]->(prd5), (p9)-[:view {time: 1460909846}]->(prd6), (p9)-[:addtocart {time: 1376191346}]->(prd7), (p9)-[:view {time: 1445321666}]->(prd0), (p9)-[:view {time: 1494459026}]->(prd4), (p9)-[:view {time: 1591052846}]->(prd2), (p9)-[:view {time: 1373205506}]->(prd9), (p9)-[:addtocart {time: 1577717966}]->(prd8), (p9)-[:view {time: 1308607406}]->(prd3), (p9)-[:view {time: 1326255626}]->(prd1), (p9)-[:addtocart {time: 1376191346}]->(prd7), (p9)-[:addtocart {time: 1577717966}]->(prd8), (o14:order {id: 14,subTotal:1088.04,tax:50.6,shipping:15.4,total:1154.04}), (p9)-[:transact {time: 1577717966}]->(o14), (o14)-[:contain]->(prd7), (p9)-[:rating {time: 1577717966, rating: 6}]->(prd7), (o14)-[:contain]->(prd8), (p9)-[:rating {time: 1577717966, rating: 4}]->(prd8)

...which, honestly, is sufficient for my needs.