Tôi đã optimize API placeOrder từ 1,1 phút xuống còn 890ms

Vài lời mở đầu

Dạo gần dây có vài khách hàng kêu dùng POS có vẻ chậm, mà cấu hình server thì khá to, tài nguyên dùng cả chục có khi trăm con POS cũng được, ấy thế mà vẫn kêu chậm. Nhân tiện một ngày dậy sớm =)) + “có thời gian” ^^, mình vào mục đích là chỉ để fix bug thôi, nhưng không ngờ nó lại ra được cái bài viết dài thế này, chia sẻ cho moi người luôn về hướng tiếp cận cũng như cách mình fix con bug này, biết đâu anh em lại tìm thấy nhiều điều mới để cải thiện sản phẩm hơn. Mọi người muốn biết kết quả thì kéo xuống cuối cùng luôn nhé ^^.

Như thường lệ để cho bài viết thêm phần hấp dẫn thì nên có phần before/after ở ngay đầu =))
Before

After

Câu chuyện

Có 1 khách hàng đang sử dụng Magestore POS, nhưng hay gặp vấn đề là thi thoảng order cứ bị vào phần unconverted order, trong khi mình check bug này thì lại thấy 1 vấn đề khác là POS tạo order rất chậm, nghe có vẻ khá thường gặp với một vài khách cụ thể khác. Nên mình quyết định là xử lý phần order chậm trước biết đâu nó là 1 phần nguyên nhân của bug ban đầu (order hay bị chuyển vào phần unconverted order) thì sao.

Cấu hình site khách hàng

  • 8 Core 64 Gb Ram
  • 40775 Products
  • 14016 Customers
  • LEMP Stack (Linux - Nginx - MariaDB - PHP FastCGI)
  • Magento CE 2.3.5-p2
  • Magestore POS Pro 4.12.3
  • Service thêm: Redis và Varnish cache để tăng tốc

Đây là ảnh server khách hàng khi mở htop, lúc nào cũng xanh lét ngay cả khi mình place order trên POS, thậm chí còn chả nhỉnh lên được vạch nào :stuck_out_tongue:

và tốc độ khi call API placeOrder trung bình khoảng hơn 60s cho 1 lần call API place order từ POS =))), lúc này các request khác đến server để get product list sau khi order cũng chậm chỉ sau khi API placeOrder xong mới nhanh hơn trở lại (nghe thì có vẻ cũng “vô ní” đấy, nhưng kết quả thì lại thuyết phục :v).

Kết luận tạm thời:

Có 3 nguyên nhân có thể gây ra chậm

  1. Phần cứng không đủ (loại ngay từ vòng gửi xe)
  2. Cấu hình memory limit trên server
  3. Code logic

Ở đây phần cứng đã rõ ràng không phải bàn cãi lên ta chỉ quan tâm đến nguyên nhân số 2 và số 3 để tập trung xử lý.

Nguyên nhân số 2

Cái đầu tiên là xem ngay phpinfo site hiện tại xem ông khách cấu hình thế nào thì thấy hình sau

Giải thích về giá trị trong ảnh:

  • Bên phải là master value cái được cài trong file php.ini
  • Bên trái là local value cái mà khi chạy script php nó sẽ sử dụng value này.

Adu vjp - 756MB ??? Server to mà set cấu hình memory limit hẻo thế này thì chạy cái quái gì trong khi minimum requirement của Magento yêu cầu 2Gb ram tối thiểu. Khả năng khách muốn tiết kiệm memory chăng - mình nghĩ trong đầu vậy

Thế là request luôn cho khách hàng tăng luôn. Lên slack nào

  • Mình: “Ông ơi ông làm ăn kiểu gì chứ server to thế này mà set memory limit bé tí teo thì làm ăn cái gì, tăng hộ tôi lên 4Gb ram được hong zị.”
  • Khách: “Ô kê, lái la lái la”
  • Khách: “Tôi tăng rồi đấy mà check place order lại chả khác quái gì”
  • Mình: “Ok để tôi check lại cái đã xem có bị vuông vành không =))”

Đoạn này mình có cải biên đi tí để tấu hài thôi

Lên check lại thấy memory limit đã đổi

Nhưng đúng là place order API thì vẫn không thay đổi gì thật =))), loanh quanh đâu đấy 1 phút đến phút rưỡi cho 1 API place order. Thôi giờ chỉ còn phương pháp cuối cùng là “debug và chửi đổng thôi”, chứ còn cách gì khác nữa đầu mà khóc với sầu :3.

Nguyên nhân số 3

Cách tiếp cận:

  • Khoanh vùng
  • Đặt log chạy qua các function nhỏ theo thời gian
  • Xem log và thời gian
  • So sánh đánh giá kết quả, lấy thằng có runtime to nhất
  • Quay lại bước 1 đến khi nào tìm ra thì thôi =)))

đầu tiên cứ là như thế đã nhở?

Sau khoảng vài thao tác xử lý cồng kềnh (Tìm Api Place Order => Interface => Model), thì mình tìm được đoạn code sau “nghe có vẻ khả nghi”

File: app/code/Magestore/Webpos/Model/Checkout/PosOrderRepository.php

Chỗ này theo phán đoán là chỉ có thằng convertPosOrderToMagentoOrder gây ra vấn đề thôi, nên mình vào trong này đặt log luôn. Cách đặt log sẽ là: Trước mỗi function cần check thì lấy timestamp rồi convert ra minisecond, qua function đó thì lại lấy time ra rồi trừ 2 thằng cho nhau ta ra được thời gian chạy cho thằng function đó - dùng thế thôi cho nó đơn giản, mình không có đòn gì cao siêu đâu :P.

Lên StackOver xem có ông nào code sẵn chưa copy về luôn cho nhanh =)), và nó đây

$milliseconds = round(microtime(true) * 1000);

Chỉnh sửa lại tí và biến nó “thành của mình” như sau =))).

Có 1 đoạn text để đầu hàm để khi view log mình biết xem nó ở chỗ nào, các phần như 2 ô khoanh đỏ phía dưới sẽ đặt vào những chỗ khả nghi để có được kết quả và đưa ra kết luận. Dưới đây là kết quả mình thu được khi đặt vào những function khả nghi:

=========Magestore\Webpos\Model\Checkout\PosOrderRepository::convertPosOrderToMagentoOrder============== [] []
[2020-11-18 16:06:05] main.ERROR: Process place order: +13 [] []
[2020-11-18 16:06:05] main.ERROR: IGNORE: +0 [] []
[2020-11-18 16:06:05] main.ERROR: createOrder: +40 [] []
[2020-11-18 16:06:05] main.ERROR: sales_order_place_after: +0 [] []
[2020-11-18 16:06:05] main.ERROR: appendReservationsAfterOrderPlacement: +205 [] []
[2020-11-18 16:07:05] main.ERROR: subtractOrderInventory: +59812 [] []
[2020-11-18 16:07:05] main.ERROR: processInvoiceAndShipment: +415 [] []

Chỗ này khả nghi nhất là ông tướng subtractOrderInventory với điểm số 59812ms ~ 60s =))), có cái để chửi rồi đây =))).

Tiếp tục đào sâu đặt debug vào function này ta được:

=========Magestore\Webpos\Model\Checkout\PosOrderRepository::subtractOrderInventory============== [] []
[2020-11-18 16:16:14] main.ERROR: getProductQty: +0 [] []
[2020-11-18 16:16:14] main.ERROR: registerProductsSale: +0 [] []
[2020-11-18 16:16:14] main.ERROR: foreach (itemsForReindex as item): +0 [] []
[2020-11-18 16:16:14] main.ERROR: updateSetOutOfStock: +84 [] []
[2020-11-18 16:16:14] main.ERROR: updateSetInStock: +75 [] []
[2020-11-18 16:17:19] main.ERROR: updateLowStockDate: +64871 [] []

Chỗ này thấy được updateLowStockDate là thằng cao nhất. Nhưng sao lại là 64871, trong khi thằng trên cả function của nó chỉ là 59812? Giải thích: vì chỗ này mình gọi place order lần 2 với qty to hơn nên số nó hơi bị lệch - lần trước đã đặt debug vào đây đâu mà có =))). Nhưng điều đó không quan trọng, quan trọng là mình sắp được chửi thề rồi, hí hí ^^.

Có vẻ là ngõ cụt khi ta chạm nhẹ vào core =))), trong này thì toàn là SQL nên giờ phải chơi kiểu khác không debug to tay nữa. Mình nghĩ sẽ dùng đến database profiler để chạy xem query nó ra làm sao - tiện thể vọc vạch tool mới luôn chứ debug to tay kiểu như trên thì không biết bao giờ mới lên người được :3.

Tiếp nào tiếp nào

Setup profiler cũng đơn giản thôi, theo các cháu thủ khoa đại học thì chỉ cần sách giáo khoa là đủ ẵm 30 điểm ko cần học thêm, nên mình cũng chỉ lên Devdocs của Magento học cách setup thôi. Thuỳ Linh: db-profiler

Lưu ý: Sau khi cài db-profiler như trên thì mỗi request ở trên pos qua API nó sẽ trả về response json như thường lệ và kèm theo 1 đoạn html ngay sau đó để hiển thị profile những query trong DB mà thằng API đó khi được goi thì nó chạy qua. Điều này dễ dẫn đến việc chết API khi client không handle được response (vì nó không phải json thuần mà), và show loading screen. Nên anh em lưu ý ở bước sửa file boostrap trong hướng dẫn thì trước khi mình bấm place order mình hãy save lại thôi, thì nó chỉ chạy db-profiler cho thằng API place order.

Anh em nhớ tách phần html ra save lại vào file và mở lên trình duyệt thì sẽ được hình đẹp như sau:

Nhiệm vụ của ta bây giờ là phải tìm được đoạn query tương ứng với function updateLowStockDate để xem mô tê của nó là cái gì. Sau khoảng vài phút tìm kiếm và compare thì mình tìm ra được đoạn query sau

slow_query

Có vẻ đúng đối tượng khả nghi rồi, nhưng bây giờ làm gì tiếp? vì nó chả mang lại thêm tí thông tin nào ngoài thời gian chạy và cái query vô duyên kia cả, chả lẽ bảo với khách đây là function của core nó chậm thế xong rồi kệ à =))). Thôi thì lại ngậm ngùi quay lại code đục tiếp xem có manh mối gì không.

VÀ…

Chúng ta lại đón giao thừa, tối qua vợ đánh chưa chừa =))))

Trong code của chúng ta đang call đến hàm mà Magento đã “mark” là deprecated, và cũng recommend đến function mới luôn, tội gì mà không đọc. Nhưng đọc vào thì cũng có vẻ kha khá giống nên theo mình không có gì bằng tay thật việc thật, thử cmn luôn vào đi xem có cả thiện gì không. Thế là mình kéo lên đầu đoạn construct, sửa lại param 1 chút để dùng với class mới của Magento recommend.

File: Source/server/app/code/Magestore/Webpos/Model/Checkout/PosOrderRepository.php

Mở lại profiler đồng thời xem timing trên browser luôn.

Kết quả:

Trước đó

Nhanh rõ rệt =))

vậy lại phải lôi query từ profilter ra xem trong này nó thay đổi cái quái gì mà kinh khủng thế.

Trông thì có vẻ chả khác cái trước là mấy, nên mới lôi 2 ông tướng ra format lại rồi compare xem thế nào. Kết quả

Trông có vẻ khác nhau mỗi website_id thôi, đành phải mò tiếp vào database xem nó có đòn gì khác biệt không.

Cũng ra tấm ra món rồi đây, giờ quay lại đục lại code phát xem thế nào =)))))

Như anh em có thể thấy ở hình trên, ở function đã deprecated thì Magento truyền 1 param là $website vào mà không dùng =))), sau đó lại luôn lấy $website_id từ default stock ra mà update - quả là nước đi này tại hạ không thể ngờ tới mà :3. Default stock ở đây có khoảng 40k sản phẩm thì chạy đoạn query kia cũng khá chuối. Thay vào đó ở bên function mới, họ dùng param mình truyền vào, mà website kia nó chả có product nào thì tốc độ tăng lên cũng là điều dễ hiểu.

Kết luận

Code logic sản phẩm trong class Magestore\Webpos\Model\Checkout\PosOrderRepository::subtractOrderInventory có gọi đến function deprecated của magento \Magento\CatalogInventory\Model\ResourceModel\Stock::updateLowStockDate, function này không được Magento optimize lại, cũng như đã bị deprecated nên không đảm bảo về mặt hiệu năng, đổi sang sử dụng function mới \Magento\CatalogInventory\Model\ResourceModel\Stock\Item::updateLowStockDate

Cảm ơn mọi người đã đọc đến cuối bài và đừng quên KUDOS nếu như cảm thấy có ích nhé =)))))

15 Likes

Bài viết chất lừ anh @oliver :love_you_gesture: :love_you_gesture: :love_you_gesture:

1 Like

Ờ Mây Zing!! Gút Chóp Em :))))

1 Like

hehe, thanks a, em nghĩ chỗ này mình có thể update vào sản phẩm được ^^

cảm ơn @anon71048603 đã đón đọc rất sớm ^^

Đúng là bài viết từ 1 lập trình viên chân chính! Good quá :)) Tìm tòi giải quyết vấn đề, đo đạc thông số cụ thể, chuẩn kỹ sư IT rồi @oliver

1 Like

@oliver Thank ông nhiều vì bài viết cực kì có ích mà rất chi tiết luôn :smiley:

Nhưng mà theo t thấy có vẻ cái này chỉ nhanh với trường hợp tạo order trên website khác và ít sản phẩm thôi chứ nếu order trên website default thì nó vẫn cứ phải check 40k sp như cũ và lại chậm :sweat_smile:

T không rõ cái này lắm nhưng trước đấy hình như có lần anh Tít cũng optimize mysql để cài với chạy site demo nhanh hơn bằng cách sửa mấy thông số này đấy. Ông thử tham khảo thêm cái này xem lúc có nhiều sp thì nó có chạy nhanh hơn không

1 Like

thanks @vincent nhé, để t check thêm phần cấu hình trên site khách như ông gợi ý xem thế nào. Nhưng đúng là checkout với default website thì vẫn chậm thật.

1 Like

Làm bài tổng kết về phương pháp test performance em POS trong dự án Trulieve để đánh giá mức chịu tải đi @oliver