From 9b4ab3d03d18ea04081ef34f3553066b86bbd014 Mon Sep 17 00:00:00 2001 From: Alex Browne Date: Sun, 26 Jul 2020 21:43:04 -0700 Subject: [PATCH 1/4] Check for already stored orders in a single batch --- db/common.go | 1 + db/dexie_implementation.go | 70 ++++++++++++++++++++++ db/sql_implementation.go | 6 +- packages/mesh-browser-lite/src/database.ts | 21 +++++++ 4 files changed, 97 insertions(+), 1 deletion(-) diff --git a/db/common.go b/db/common.go index 15f41ef89..f05d63a56 100644 --- a/db/common.go +++ b/db/common.go @@ -33,6 +33,7 @@ var ( type Database interface { AddOrders(orders []*types.OrderWithMetadata) (added []*types.OrderWithMetadata, removed []*types.OrderWithMetadata, err error) GetOrder(hash common.Hash) (*types.OrderWithMetadata, error) + GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) FindOrders(opts *OrderQuery) ([]*types.OrderWithMetadata, error) CountOrders(opts *OrderQuery) (int, error) DeleteOrder(hash common.Hash) error diff --git a/db/dexie_implementation.go b/db/dexie_implementation.go index 9b1286852..18b9cb01d 100644 --- a/db/dexie_implementation.go +++ b/db/dexie_implementation.go @@ -10,15 +10,20 @@ import ( "path/filepath" "runtime/debug" "syscall/js" + "time" "github.com/0xProject/0x-mesh/common/types" "github.com/0xProject/0x-mesh/db/dexietypes" "github.com/0xProject/0x-mesh/packages/mesh-browser/go/jsutil" + "github.com/davecgh/go-spew/spew" "github.com/ethereum/go-ethereum/common" "github.com/gibson042/canonicaljson-go" "github.com/google/uuid" + "github.com/sirupsen/logrus" ) +const slowQueryDuration = 1 * time.Second + var _ Database = (*DB)(nil) type DB struct { @@ -84,6 +89,8 @@ func (db *DB) AddOrders(orders []*types.OrderWithMetadata) (added []*types.Order err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("AddOrders with %d orders", len(orders))) jsOrders, err := jsutil.InefficientlyConvertToJS(dexietypes.OrdersFromCommonType(orders)) if err != nil { return nil, nil, err @@ -111,6 +118,8 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "GetOrder") jsOrder, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getOrderAsync", hash.Hex())) if err != nil { return nil, convertJSError(err) @@ -122,6 +131,29 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er return dexietypes.OrderToCommonType(&dexieOrder), nil } +func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) { + defer func() { + if r := recover(); r != nil { + err = recoverError(r) + } + }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("GetOrderStatuses with %d hashes", len(hashes))) + stringHashes := make([]interface{}, len(hashes)) + for i, hash := range hashes { + stringHashes[i] = hash.Hex() + } + jsResults, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getOrderStatusesAsync", stringHashes)) + if err != nil { + return nil, convertJSError(err) + } + statuses = make([]int, jsResults.Length()) + for i := 0; i < len(statuses); i++ { + statuses[i] = jsResults.Index(i).Int() + } + return statuses, nil +} + func (db *DB) FindOrders(query *OrderQuery) (orders []*types.OrderWithMetadata, err error) { if err := checkOrderQuery(query); err != nil { return nil, err @@ -131,6 +163,8 @@ func (db *DB) FindOrders(query *OrderQuery) (orders []*types.OrderWithMetadata, err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("FindOrders %s", spew.Sdump(query))) query = formatOrderQuery(query) jsOrders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("findOrdersAsync", query)) if err != nil { @@ -152,6 +186,8 @@ func (db *DB) CountOrders(query *OrderQuery) (count int, err error) { err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("CountOrders %s", spew.Sdump(query))) query = formatOrderQuery(query) jsCount, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("countOrdersAsync", query)) if err != nil { @@ -166,6 +202,8 @@ func (db *DB) DeleteOrder(hash common.Hash) (err error) { err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "DeleteOrder") _, jsErr := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteOrderAsync", hash.Hex())) if jsErr != nil { return convertJSError(jsErr) @@ -182,6 +220,8 @@ func (db *DB) DeleteOrders(query *OrderQuery) (deletedOrders []*types.OrderWithM err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("DeleteOrders %s", spew.Sdump(query))) query = formatOrderQuery(query) jsOrders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteOrdersAsync", query)) if err != nil { @@ -200,6 +240,8 @@ func (db *DB) UpdateOrder(hash common.Hash, updateFunc func(existingOrder *types err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "UpdateOrder") jsUpdateFunc := js.FuncOf(func(_ js.Value, args []js.Value) interface{} { jsExistingOrder := args[0] var dexieExistingOrder dexietypes.Order @@ -231,6 +273,8 @@ func (db *DB) AddMiniHeaders(miniHeaders []*types.MiniHeader) (added []*types.Mi err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("AddMiniHeaders with %d miniHeaders", len(miniHeaders))) jsMiniHeaders := dexietypes.MiniHeadersFromCommonType(miniHeaders) jsResult, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("addMiniHeadersAsync", jsMiniHeaders)) if err != nil { @@ -249,6 +293,8 @@ func (db *DB) ResetMiniHeaders(newMiniHeaders []*types.MiniHeader) (err error) { err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("ResetMiniHeaders with %d newMiniHeaders", len(newMiniHeaders))) jsNewMiniHeaders := dexietypes.MiniHeadersFromCommonType(newMiniHeaders) _, err = jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("resetMiniHeadersAsync", jsNewMiniHeaders)) if err != nil { @@ -263,6 +309,8 @@ func (db *DB) GetMiniHeader(hash common.Hash) (miniHeader *types.MiniHeader, err err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "GetMiniHeader") jsMiniHeader, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getMiniHeaderAsync", hash.Hex())) if err != nil { return nil, convertJSError(err) @@ -279,6 +327,8 @@ func (db *DB) FindMiniHeaders(query *MiniHeaderQuery) (miniHeaders []*types.Mini err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("FindMiniHeaders %s", spew.Sdump(query))) query = formatMiniHeaderQuery(query) jsMiniHeaders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("findMiniHeadersAsync", query)) if err != nil { @@ -293,6 +343,8 @@ func (db *DB) DeleteMiniHeader(hash common.Hash) (err error) { err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "DeleteMiniHeader") _, jsErr := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteMiniHeaderAsync", hash.Hex())) if jsErr != nil { return convertJSError(jsErr) @@ -309,6 +361,8 @@ func (db *DB) DeleteMiniHeaders(query *MiniHeaderQuery) (deleted []*types.MiniHe err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, fmt.Sprintf("DeleteMiniHeaders %s", spew.Sdump(query))) query = formatMiniHeaderQuery(query) jsMiniHeaders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteMiniHeadersAsync", query)) if err != nil { @@ -323,6 +377,8 @@ func (db *DB) GetMetadata() (metadata *types.Metadata, err error) { err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "GetMetadata") jsMetadata, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getMetadataAsync")) if err != nil { return nil, convertJSError(err) @@ -340,6 +396,8 @@ func (db *DB) SaveMetadata(metadata *types.Metadata) (err error) { err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "SaveMetadata") dexieMetadata := dexietypes.MetadataFromCommonType(metadata) jsMetadata, err := jsutil.InefficientlyConvertToJS(dexieMetadata) if err != nil { @@ -358,6 +416,8 @@ func (db *DB) UpdateMetadata(updateFunc func(oldmetadata *types.Metadata) (newMe err = recoverError(r) } }() + start := time.Now() + defer logDuration(start, "UpdateMetadata") jsUpdateFunc := js.FuncOf(func(_ js.Value, args []js.Value) interface{} { jsExistingMetadata := args[0] var dexieExistingMetadata dexietypes.Metadata @@ -461,3 +521,13 @@ func assetDataIncludesTokenAddressAndTokenID(field OrderField, tokenAddress comm Value: string(filterValueJSON), } } + +func logDuration(start time.Time, msg string) { + duration := time.Since(start) + if duration > slowQueryDuration { + logrus.WithFields(logrus.Fields{ + "message": msg, + "duration": fmt.Sprint(duration), + }).Error("slow query") + } +} diff --git a/db/sql_implementation.go b/db/sql_implementation.go index fc44d1a9a..ea52450cf 100644 --- a/db/sql_implementation.go +++ b/db/sql_implementation.go @@ -353,6 +353,10 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er return sqltypes.OrderToCommonType(&foundOrder), nil } +func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) { + return nil, errors.New("not yet implemented") +} + func (db *DB) FindOrders(query *OrderQuery) (orders []*types.OrderWithMetadata, err error) { defer func() { err = convertErr(err) @@ -386,7 +390,7 @@ func (db *DB) CountOrders(query *OrderQuery) (count int, err error) { return 0, err } db.mu.RLock() - gotCount, err := stmt.GetCount() + gotCount, err := stmt.GetCountContext(db.ctx) db.mu.RUnlock() if err != nil { return 0, err diff --git a/packages/mesh-browser-lite/src/database.ts b/packages/mesh-browser-lite/src/database.ts index 17e8b91a4..f71220cb1 100644 --- a/packages/mesh-browser-lite/src/database.ts +++ b/packages/mesh-browser-lite/src/database.ts @@ -221,6 +221,27 @@ export class Database { }); } + // GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) + public async getOrderStatusesAsync(hashes: string[]): Promise { + const statuses: number[] = []; + await this._db.transaction('rw!', this._orders, async () => { + for (const hash of hashes) { + const order = await this._orders.get(hash); + if (order === undefined) { + // 0 means not stored + statuses.push(0); + } else if (order.isRemoved) { + // 1 means stored but marked as removed + statuses.push(1); + } else { + // 2 means store and not marked as removed + statuses.push(2); + } + } + }); + return statuses; + } + // FindOrders(opts *OrderQuery) ([]*types.OrderWithMetadata, error) public async findOrdersAsync(query?: OrderQuery): Promise { return this._db.transaction('rw!', this._orders, async () => { From ec982d7ca96ac805248e9016557b0d2e2928c028 Mon Sep 17 00:00:00 2001 From: Alex Browne Date: Sun, 26 Jul 2020 21:49:42 -0700 Subject: [PATCH 2/4] Use new method in orderwatcher --- zeroex/orderwatch/order_watcher.go | 77 ++++++++++++++++-------------- 1 file changed, 41 insertions(+), 36 deletions(-) diff --git a/zeroex/orderwatch/order_watcher.go b/zeroex/orderwatch/order_watcher.go index 128a052a0..cea7f0417 100644 --- a/zeroex/orderwatch/order_watcher.go +++ b/zeroex/orderwatch/order_watcher.go @@ -1257,15 +1257,14 @@ func (w *Watcher) generateOrderEventsIfChanged( // ValidateAndStoreValidOrders applies general 0x validation and Mesh-specific validation to // the given orders and if they are valid, adds them to the OrderWatcher func (w *Watcher) ValidateAndStoreValidOrders(ctx context.Context, orders []*zeroex.SignedOrder, pinned bool, chainID int) (*ordervalidator.ValidationResults, error) { + if len(orders) == 0 { + return &ordervalidator.ValidationResults{}, nil + } results, validMeshOrders, err := w.meshSpecificOrderValidation(orders, chainID, pinned) if err != nil { return nil, err } - // Lock down the processing of additional block events until we've validated and added these new orders - w.handleBlockEventsMu.RLock() - defer w.handleBlockEventsMu.RUnlock() - validationBlock, zeroexResults, err := w.onchainOrderValidation(ctx, validMeshOrders) if err != nil { return nil, err @@ -1360,6 +1359,7 @@ func (w *Watcher) meshSpecificOrderValidation(orders []*zeroex.SignedOrder, chai } } + validOrderHashes := []common.Hash{} for _, order := range orders { orderHash, err := order.ComputeOrderHash() if err != nil { @@ -1442,41 +1442,46 @@ func (w *Watcher) meshSpecificOrderValidation(orders []*zeroex.SignedOrder, chai } } - // Check if order is already stored in DB - dbOrder, err := w.db.GetOrder(orderHash) - if err != nil { - if err != db.ErrNotFound { - logger.WithField("error", err).Error("could not check if order was already stored") - return nil, nil, err - } - // If the error is db.ErrNotFound, it just means the order is not currently stored in - // the database. There's nothing else in the database to check, so we can continue. - } else { - // If stored but flagged for removal, reject it - if dbOrder.IsRemoved { - results.Rejected = append(results.Rejected, &ordervalidator.RejectedOrderInfo{ - OrderHash: orderHash, - SignedOrder: order, - Kind: ordervalidator.MeshValidation, - Status: ordervalidator.ROOrderAlreadyStoredAndUnfillable, - }) - continue - } else { - // If stored but not flagged for removal, accept it without re-validation - results.Accepted = append(results.Accepted, &ordervalidator.AcceptedOrderInfo{ - OrderHash: orderHash, - SignedOrder: order, - FillableTakerAssetAmount: dbOrder.FillableTakerAssetAmount, - IsNew: false, - }) - continue - } - } - + validOrderHashes = append(validOrderHashes, orderHash) validMeshOrders = append(validMeshOrders, order) } - return results, validMeshOrders, nil + newValidOrders := []*zeroex.SignedOrder{} + storedOrderStatuses, err := w.db.GetOrderStatuses(validOrderHashes) + if err != nil { + logger.WithField("error", err).Error("could not get stored order statuses") + return nil, nil, err + } + if len(storedOrderStatuses) != len(validOrderHashes) { + return nil, nil, errors.New("could not get stored order statuses for all orders") + } + for i, order := range validMeshOrders { + orderStatus := storedOrderStatuses[i] + orderHash := validOrderHashes[i] + switch orderStatus { + case 0: + newValidOrders = append(newValidOrders, order) + case 1: + // If stored but marked as removed, reject the order. + results.Rejected = append(results.Rejected, &ordervalidator.RejectedOrderInfo{ + OrderHash: orderHash, + SignedOrder: order, + Kind: ordervalidator.MeshValidation, + Status: ordervalidator.ROOrderAlreadyStoredAndUnfillable, + }) + case 2: + // If stored but not marked as removed, accept the order without re-validation + results.Accepted = append(results.Accepted, &ordervalidator.AcceptedOrderInfo{ + OrderHash: orderHash, + SignedOrder: order, + // FIXME(albrow): return the actual FillableTakerAssetAmount. + FillableTakerAssetAmount: big.NewInt(0), + IsNew: false, + }) + } + } + + return results, newValidOrders, nil } func validateOrderSize(order *zeroex.SignedOrder) error { From 9af96299a4f02b40a9c2499411b9c5e317c2c5a6 Mon Sep 17 00:00:00 2001 From: Alex Browne Date: Sun, 26 Jul 2020 22:10:40 -0700 Subject: [PATCH 3/4] Change return value for GetOrderStatuses to include fillable amount --- db/common.go | 8 +++++- db/dexie_implementation.go | 12 ++++++-- db/sql_implementation.go | 2 +- packages/mesh-browser-lite/src/database.ts | 33 ++++++++++++++++------ zeroex/orderwatch/order_watcher.go | 15 +++++----- 5 files changed, 48 insertions(+), 22 deletions(-) diff --git a/db/common.go b/db/common.go index f05d63a56..825359bd8 100644 --- a/db/common.go +++ b/db/common.go @@ -33,7 +33,7 @@ var ( type Database interface { AddOrders(orders []*types.OrderWithMetadata) (added []*types.OrderWithMetadata, removed []*types.OrderWithMetadata, err error) GetOrder(hash common.Hash) (*types.OrderWithMetadata, error) - GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) + GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) FindOrders(opts *OrderQuery) ([]*types.OrderWithMetadata, error) CountOrders(opts *OrderQuery) (int, error) DeleteOrder(hash common.Hash) error @@ -140,6 +140,12 @@ type OrderFilter struct { Value interface{} `json:"value"` } +type StoredOrderStatus struct { + IsStored bool `json:"isStored"` + IsMarkedRemoved bool `json:"isMarkedRemoved"` + FillableTakerAssetAmount *big.Int `json:"fillableTakerAssetAmount"` +} + // MakerAssetIncludesTokenAddressAndTokenID is a helper method which returns a filter that will match orders // that include the token address and token ID in MakerAssetData. func MakerAssetIncludesTokenAddressAndTokenID(tokenAddress common.Address, tokenID *big.Int) OrderFilter { diff --git a/db/dexie_implementation.go b/db/dexie_implementation.go index 18b9cb01d..12d5ba51e 100644 --- a/db/dexie_implementation.go +++ b/db/dexie_implementation.go @@ -131,7 +131,7 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er return dexietypes.OrderToCommonType(&dexieOrder), nil } -func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) { +func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) { defer func() { if r := recover(); r != nil { err = recoverError(r) @@ -147,9 +147,15 @@ func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) if err != nil { return nil, convertJSError(err) } - statuses = make([]int, jsResults.Length()) + statuses = make([]StoredOrderStatus, jsResults.Length()) for i := 0; i < len(statuses); i++ { - statuses[i] = jsResults.Index(i).Int() + jsStatus := jsResults.Index(i) + fillableTakerAssetAmount, _ := big.NewInt(0).SetString(jsStatus.Get("fillableTakerAssetAmount").String(), 10) + statuses[i] = StoredOrderStatus{ + IsStored: jsStatus.Get("isStored").Bool(), + IsMarkedRemoved: jsStatus.Get("isMarkedRemoved").Bool(), + FillableTakerAssetAmount: fillableTakerAssetAmount, + } } return statuses, nil } diff --git a/db/sql_implementation.go b/db/sql_implementation.go index ea52450cf..6b89cc6fd 100644 --- a/db/sql_implementation.go +++ b/db/sql_implementation.go @@ -353,7 +353,7 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er return sqltypes.OrderToCommonType(&foundOrder), nil } -func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) { +func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) { return nil, errors.New("not yet implemented") } diff --git a/packages/mesh-browser-lite/src/database.ts b/packages/mesh-browser-lite/src/database.ts index f71220cb1..1a6e91d71 100644 --- a/packages/mesh-browser-lite/src/database.ts +++ b/packages/mesh-browser-lite/src/database.ts @@ -82,6 +82,12 @@ export interface Order { lastValidatedBlockHash: string; } +export interface StoredOrderStatus { + isStored: boolean; + isMarkedRemoved: boolean; + fillableTakerAssetAmount: string; +} + export type OrderField = keyof Order; export type OrderQuery = Query; @@ -221,21 +227,30 @@ export class Database { }); } - // GetOrderStatuses(hashes []common.Hash) (statuses []int, err error) - public async getOrderStatusesAsync(hashes: string[]): Promise { - const statuses: number[] = []; + // GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) + public async getOrderStatusesAsync(hashes: string[]): Promise { + const statuses: StoredOrderStatus[] = []; await this._db.transaction('rw!', this._orders, async () => { for (const hash of hashes) { const order = await this._orders.get(hash); if (order === undefined) { - // 0 means not stored - statuses.push(0); + statuses.push({ + isStored: false, + isMarkedRemoved: false, + fillableTakerAssetAmount: '0', + }); } else if (order.isRemoved) { - // 1 means stored but marked as removed - statuses.push(1); + statuses.push({ + isStored: true, + isMarkedRemoved: true, + fillableTakerAssetAmount: order.fillableTakerAssetAmount, + }); } else { - // 2 means store and not marked as removed - statuses.push(2); + statuses.push({ + isStored: true, + isMarkedRemoved: false, + fillableTakerAssetAmount: order.fillableTakerAssetAmount, + }); } } }); diff --git a/zeroex/orderwatch/order_watcher.go b/zeroex/orderwatch/order_watcher.go index cea7f0417..3c6d7178f 100644 --- a/zeroex/orderwatch/order_watcher.go +++ b/zeroex/orderwatch/order_watcher.go @@ -1458,10 +1458,10 @@ func (w *Watcher) meshSpecificOrderValidation(orders []*zeroex.SignedOrder, chai for i, order := range validMeshOrders { orderStatus := storedOrderStatuses[i] orderHash := validOrderHashes[i] - switch orderStatus { - case 0: + if !orderStatus.IsStored { + // If not stored, add the order to a set of new orders. newValidOrders = append(newValidOrders, order) - case 1: + } else if orderStatus.IsMarkedRemoved { // If stored but marked as removed, reject the order. results.Rejected = append(results.Rejected, &ordervalidator.RejectedOrderInfo{ OrderHash: orderHash, @@ -1469,13 +1469,12 @@ func (w *Watcher) meshSpecificOrderValidation(orders []*zeroex.SignedOrder, chai Kind: ordervalidator.MeshValidation, Status: ordervalidator.ROOrderAlreadyStoredAndUnfillable, }) - case 2: + } else { // If stored but not marked as removed, accept the order without re-validation results.Accepted = append(results.Accepted, &ordervalidator.AcceptedOrderInfo{ - OrderHash: orderHash, - SignedOrder: order, - // FIXME(albrow): return the actual FillableTakerAssetAmount. - FillableTakerAssetAmount: big.NewInt(0), + OrderHash: orderHash, + SignedOrder: order, + FillableTakerAssetAmount: orderStatus.FillableTakerAssetAmount, IsNew: false, }) } From e31c431f848a2998416ce67592379957543bfd52 Mon Sep 17 00:00:00 2001 From: Alex Browne Date: Mon, 27 Jul 2020 10:36:35 -0700 Subject: [PATCH 4/4] Implement GetOrderStatuses in SQL; Update log levels --- db/common.go | 2 +- db/db_test.go | 38 ++++++++++++ db/dexie_implementation.go | 70 +++++++++++++--------- db/sql_implementation.go | 41 ++++++++++++- packages/mesh-browser-lite/src/database.ts | 3 +- 5 files changed, 122 insertions(+), 32 deletions(-) diff --git a/db/common.go b/db/common.go index 825359bd8..f8eae7b5e 100644 --- a/db/common.go +++ b/db/common.go @@ -33,7 +33,7 @@ var ( type Database interface { AddOrders(orders []*types.OrderWithMetadata) (added []*types.OrderWithMetadata, removed []*types.OrderWithMetadata, err error) GetOrder(hash common.Hash) (*types.OrderWithMetadata, error) - GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) + GetOrderStatuses(hashes []common.Hash) (statuses []*StoredOrderStatus, err error) FindOrders(opts *OrderQuery) ([]*types.OrderWithMetadata, error) CountOrders(opts *OrderQuery) (int, error) DeleteOrder(hash common.Hash) error diff --git a/db/db_test.go b/db/db_test.go index 8700eab7d..b8267c9ad 100644 --- a/db/db_test.go +++ b/db/db_test.go @@ -164,6 +164,44 @@ func TestGetOrder(t *testing.T) { assert.EqualError(t, err, ErrNotFound.Error(), "calling GetOrder with a hash that doesn't exist should return ErrNotFound") } +func TestGetOrderStatuses(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + db := newTestDB(t, ctx) + + removedOrder := newTestOrder() + removedOrder.IsRemoved = true + notRemovedOrder := newTestOrder() + _, _, err := db.AddOrders([]*types.OrderWithMetadata{removedOrder, notRemovedOrder}) + require.NoError(t, err) + + hashes := []common.Hash{ + common.HexToHash("0xace746910c6a8a4730878e6e8a4abb328844c0b58f0cdfbb5b6ad28ee0bae347"), + removedOrder.Hash, + notRemovedOrder.Hash, + } + actualStatuses, err := db.GetOrderStatuses(hashes) + require.NoError(t, err) + expectedStatuses := []*StoredOrderStatus{ + { + IsStored: false, + IsMarkedRemoved: false, + FillableTakerAssetAmount: nil, + }, + { + IsStored: true, + IsMarkedRemoved: true, + FillableTakerAssetAmount: removedOrder.FillableTakerAssetAmount, + }, + { + IsStored: true, + IsMarkedRemoved: false, + FillableTakerAssetAmount: notRemovedOrder.FillableTakerAssetAmount, + }, + } + assert.Equal(t, expectedStatuses, actualStatuses) +} + func TestGetCurrentMaxExpirationTime(t *testing.T) { ctx, cancel := context.WithCancel(context.Background()) defer cancel() diff --git a/db/dexie_implementation.go b/db/dexie_implementation.go index 12d5ba51e..4b243c7ed 100644 --- a/db/dexie_implementation.go +++ b/db/dexie_implementation.go @@ -22,7 +22,14 @@ import ( "github.com/sirupsen/logrus" ) -const slowQueryDuration = 1 * time.Second +const ( + // slowQueryDebugDuration is the minimum duration used to determine whether to log slow queries. + // Any query that takes longer than this will be logged at the Debug level. + slowQueryDebugDuration = 1 * time.Second + // slowQueryWarnDuration is the minimum duration used to determine whether to log slow queries. + // Any query that takes longer than this will be logged at the Warning level. + slowQueryWarnDuration = 5 * time.Second +) var _ Database = (*DB)(nil) @@ -90,7 +97,7 @@ func (db *DB) AddOrders(orders []*types.OrderWithMetadata) (added []*types.Order } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("AddOrders with %d orders", len(orders))) + defer logQueryIfSlow(start, fmt.Sprintf("AddOrders with %d orders", len(orders))) jsOrders, err := jsutil.InefficientlyConvertToJS(dexietypes.OrdersFromCommonType(orders)) if err != nil { return nil, nil, err @@ -119,7 +126,7 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er } }() start := time.Now() - defer logDuration(start, "GetOrder") + defer logQueryIfSlow(start, "GetOrder") jsOrder, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getOrderAsync", hash.Hex())) if err != nil { return nil, convertJSError(err) @@ -131,14 +138,14 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er return dexietypes.OrderToCommonType(&dexieOrder), nil } -func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) { +func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []*StoredOrderStatus, err error) { defer func() { if r := recover(); r != nil { err = recoverError(r) } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("GetOrderStatuses with %d hashes", len(hashes))) + defer logQueryIfSlow(start, fmt.Sprintf("GetOrderStatuses with %d hashes", len(hashes))) stringHashes := make([]interface{}, len(hashes)) for i, hash := range hashes { stringHashes[i] = hash.Hex() @@ -147,14 +154,18 @@ func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStat if err != nil { return nil, convertJSError(err) } - statuses = make([]StoredOrderStatus, jsResults.Length()) + statuses = make([]*StoredOrderStatus, jsResults.Length()) for i := 0; i < len(statuses); i++ { jsStatus := jsResults.Index(i) - fillableTakerAssetAmount, _ := big.NewInt(0).SetString(jsStatus.Get("fillableTakerAssetAmount").String(), 10) - statuses[i] = StoredOrderStatus{ + var fillableAmount *big.Int + jsAmount := jsStatus.Get("fillableTakerAssetAmount") + if !jsutil.IsNullOrUndefined(jsAmount) { + fillableAmount, _ = big.NewInt(0).SetString(jsAmount.String(), 10) + } + statuses[i] = &StoredOrderStatus{ IsStored: jsStatus.Get("isStored").Bool(), IsMarkedRemoved: jsStatus.Get("isMarkedRemoved").Bool(), - FillableTakerAssetAmount: fillableTakerAssetAmount, + FillableTakerAssetAmount: fillableAmount, } } return statuses, nil @@ -170,7 +181,7 @@ func (db *DB) FindOrders(query *OrderQuery) (orders []*types.OrderWithMetadata, } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("FindOrders %s", spew.Sdump(query))) + defer logQueryIfSlow(start, fmt.Sprintf("FindOrders %s", spew.Sdump(query))) query = formatOrderQuery(query) jsOrders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("findOrdersAsync", query)) if err != nil { @@ -193,7 +204,7 @@ func (db *DB) CountOrders(query *OrderQuery) (count int, err error) { } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("CountOrders %s", spew.Sdump(query))) + defer logQueryIfSlow(start, fmt.Sprintf("CountOrders %s", spew.Sdump(query))) query = formatOrderQuery(query) jsCount, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("countOrdersAsync", query)) if err != nil { @@ -209,7 +220,7 @@ func (db *DB) DeleteOrder(hash common.Hash) (err error) { } }() start := time.Now() - defer logDuration(start, "DeleteOrder") + defer logQueryIfSlow(start, "DeleteOrder") _, jsErr := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteOrderAsync", hash.Hex())) if jsErr != nil { return convertJSError(jsErr) @@ -227,7 +238,7 @@ func (db *DB) DeleteOrders(query *OrderQuery) (deletedOrders []*types.OrderWithM } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("DeleteOrders %s", spew.Sdump(query))) + defer logQueryIfSlow(start, fmt.Sprintf("DeleteOrders %s", spew.Sdump(query))) query = formatOrderQuery(query) jsOrders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteOrdersAsync", query)) if err != nil { @@ -247,7 +258,7 @@ func (db *DB) UpdateOrder(hash common.Hash, updateFunc func(existingOrder *types } }() start := time.Now() - defer logDuration(start, "UpdateOrder") + defer logQueryIfSlow(start, "UpdateOrder") jsUpdateFunc := js.FuncOf(func(_ js.Value, args []js.Value) interface{} { jsExistingOrder := args[0] var dexieExistingOrder dexietypes.Order @@ -280,7 +291,7 @@ func (db *DB) AddMiniHeaders(miniHeaders []*types.MiniHeader) (added []*types.Mi } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("AddMiniHeaders with %d miniHeaders", len(miniHeaders))) + defer logQueryIfSlow(start, fmt.Sprintf("AddMiniHeaders with %d miniHeaders", len(miniHeaders))) jsMiniHeaders := dexietypes.MiniHeadersFromCommonType(miniHeaders) jsResult, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("addMiniHeadersAsync", jsMiniHeaders)) if err != nil { @@ -300,7 +311,7 @@ func (db *DB) ResetMiniHeaders(newMiniHeaders []*types.MiniHeader) (err error) { } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("ResetMiniHeaders with %d newMiniHeaders", len(newMiniHeaders))) + defer logQueryIfSlow(start, fmt.Sprintf("ResetMiniHeaders with %d newMiniHeaders", len(newMiniHeaders))) jsNewMiniHeaders := dexietypes.MiniHeadersFromCommonType(newMiniHeaders) _, err = jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("resetMiniHeadersAsync", jsNewMiniHeaders)) if err != nil { @@ -316,7 +327,7 @@ func (db *DB) GetMiniHeader(hash common.Hash) (miniHeader *types.MiniHeader, err } }() start := time.Now() - defer logDuration(start, "GetMiniHeader") + defer logQueryIfSlow(start, "GetMiniHeader") jsMiniHeader, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getMiniHeaderAsync", hash.Hex())) if err != nil { return nil, convertJSError(err) @@ -334,7 +345,7 @@ func (db *DB) FindMiniHeaders(query *MiniHeaderQuery) (miniHeaders []*types.Mini } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("FindMiniHeaders %s", spew.Sdump(query))) + defer logQueryIfSlow(start, fmt.Sprintf("FindMiniHeaders %s", spew.Sdump(query))) query = formatMiniHeaderQuery(query) jsMiniHeaders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("findMiniHeadersAsync", query)) if err != nil { @@ -350,7 +361,7 @@ func (db *DB) DeleteMiniHeader(hash common.Hash) (err error) { } }() start := time.Now() - defer logDuration(start, "DeleteMiniHeader") + defer logQueryIfSlow(start, "DeleteMiniHeader") _, jsErr := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteMiniHeaderAsync", hash.Hex())) if jsErr != nil { return convertJSError(jsErr) @@ -368,7 +379,7 @@ func (db *DB) DeleteMiniHeaders(query *MiniHeaderQuery) (deleted []*types.MiniHe } }() start := time.Now() - defer logDuration(start, fmt.Sprintf("DeleteMiniHeaders %s", spew.Sdump(query))) + defer logQueryIfSlow(start, fmt.Sprintf("DeleteMiniHeaders %s", spew.Sdump(query))) query = formatMiniHeaderQuery(query) jsMiniHeaders, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("deleteMiniHeadersAsync", query)) if err != nil { @@ -384,7 +395,7 @@ func (db *DB) GetMetadata() (metadata *types.Metadata, err error) { } }() start := time.Now() - defer logDuration(start, "GetMetadata") + defer logQueryIfSlow(start, "GetMetadata") jsMetadata, err := jsutil.AwaitPromiseContext(db.ctx, db.dexie.Call("getMetadataAsync")) if err != nil { return nil, convertJSError(err) @@ -403,7 +414,7 @@ func (db *DB) SaveMetadata(metadata *types.Metadata) (err error) { } }() start := time.Now() - defer logDuration(start, "SaveMetadata") + defer logQueryIfSlow(start, "SaveMetadata") dexieMetadata := dexietypes.MetadataFromCommonType(metadata) jsMetadata, err := jsutil.InefficientlyConvertToJS(dexieMetadata) if err != nil { @@ -423,7 +434,7 @@ func (db *DB) UpdateMetadata(updateFunc func(oldmetadata *types.Metadata) (newMe } }() start := time.Now() - defer logDuration(start, "UpdateMetadata") + defer logQueryIfSlow(start, "UpdateMetadata") jsUpdateFunc := js.FuncOf(func(_ js.Value, args []js.Value) interface{} { jsExistingMetadata := args[0] var dexieExistingMetadata dexietypes.Metadata @@ -528,12 +539,17 @@ func assetDataIncludesTokenAddressAndTokenID(field OrderField, tokenAddress comm } } -func logDuration(start time.Time, msg string) { +func logQueryIfSlow(start time.Time, msg string) { duration := time.Since(start) - if duration > slowQueryDuration { - logrus.WithFields(logrus.Fields{ + if duration > slowQueryDebugDuration { + logWithFields := logrus.WithFields(logrus.Fields{ "message": msg, "duration": fmt.Sprint(duration), - }).Error("slow query") + }) + if duration > slowQueryWarnDuration { + logWithFields.Warn("slow query") + } else { + logWithFields.Debug("slow query") + } } } diff --git a/db/sql_implementation.go b/db/sql_implementation.go index 6b89cc6fd..dfbd59e8d 100644 --- a/db/sql_implementation.go +++ b/db/sql_implementation.go @@ -353,8 +353,45 @@ func (db *DB) GetOrder(hash common.Hash) (order *types.OrderWithMetadata, err er return sqltypes.OrderToCommonType(&foundOrder), nil } -func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []StoredOrderStatus, err error) { - return nil, errors.New("not yet implemented") +func (db *DB) GetOrderStatuses(hashes []common.Hash) (statuses []*StoredOrderStatus, err error) { + defer func() { + err = convertErr(err) + }() + orderStatuses := make([]*StoredOrderStatus, len(hashes)) + err = db.ReadWriteTransactionalContext(db.ctx, nil, func(txn *sqlz.Tx) error { + for i, hash := range hashes { + var foundOrder sqltypes.Order + err := db.sqldb.GetContext(db.ctx, &foundOrder, "SELECT isRemoved, fillableTakerAssetAmount FROM orders WHERE hash = $1", hash) + if err != nil { + if err == sql.ErrNoRows { + orderStatuses[i] = &StoredOrderStatus{ + IsStored: false, + IsMarkedRemoved: false, + FillableTakerAssetAmount: nil, + } + } else { + return err + } + } else if foundOrder.IsRemoved { + orderStatuses[i] = &StoredOrderStatus{ + IsStored: true, + IsMarkedRemoved: true, + FillableTakerAssetAmount: foundOrder.FillableTakerAssetAmount.Int, + } + } else { + orderStatuses[i] = &StoredOrderStatus{ + IsStored: true, + IsMarkedRemoved: false, + FillableTakerAssetAmount: foundOrder.FillableTakerAssetAmount.Int, + } + } + } + return nil + }) + if err != nil { + return nil, err + } + return orderStatuses, nil } func (db *DB) FindOrders(query *OrderQuery) (orders []*types.OrderWithMetadata, err error) { diff --git a/packages/mesh-browser-lite/src/database.ts b/packages/mesh-browser-lite/src/database.ts index 1a6e91d71..550bc72df 100644 --- a/packages/mesh-browser-lite/src/database.ts +++ b/packages/mesh-browser-lite/src/database.ts @@ -85,7 +85,7 @@ export interface Order { export interface StoredOrderStatus { isStored: boolean; isMarkedRemoved: boolean; - fillableTakerAssetAmount: string; + fillableTakerAssetAmount?: string; } export type OrderField = keyof Order; @@ -237,7 +237,6 @@ export class Database { statuses.push({ isStored: false, isMarkedRemoved: false, - fillableTakerAssetAmount: '0', }); } else if (order.isRemoved) { statuses.push({