Menu ▾ ▴

#2868 imm: sync message size could be over the maximum size of MDS buf

5.21.09
not-reproducible
Hieu Hong Hoang
None
defect
imm
-
major
False
2021-09-14
2018-05-28
Vu Minh Nguyen
No

To speed up IMM sync process, osafimmloadd packs a bunch of IMM class objects in one package and sends to IMMND coordinator in one go. The size of the package could be adjustable via the configurable attribute opensafImmSyncBatchSize which has the default value around 90% of MDS_DIRECT_BUF_MAXSIZE.

With current code, objects will be pushed into the batch as long as the space which is 90% of opensafImmSyncBatchSize still remains - is larger than zero.

If the remaining space is quite small and the size of next going-to-pushed object is quite big, the package size could be over MDS_DIRECT_BUF_MAXSIZE. When that huge package arrives at the active IMMD, it will fail to broadcast the messages with syslog:

SC-1 osafimmd[xxx]: NO MDTM: Not possible to send size:65262 TIPC multicast to svc_id = IMMND(25)

Here is osafimmloadd's trace to show up the case:

<143>1 2018-05-28T11:59:06.743861+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6348"] 846:imm/agent/imma_om_api.cc:7094 TR Remaining space:539
<143>1 2018-05-28T11:59:06.74391+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6349"] 846:imm/agent/imma_om_api.cc:7117 << immsv_sync
<143>1 2018-05-28T11:59:06.743959+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6350"] 846:imm/immloadd/imm_loader.cc:2374 TR SA_AIS_ERR_NOT_READY => BUFFERED
<143>1 2018-05-28T11:59:06.744007+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6351"] 846:imm/immloadd/imm_loader.cc:2382 TR Synced object: safLgStrCfg=test_90,safLgStrCfg=test
<143>1 2018-05-28T11:59:06.744364+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6352"] 848:mds/mds_dt_trans.c:755 >> mdtm_process_poll_recv_data_tcp
<143>1 2018-05-28T11:59:06.744518+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6353"] 846:imm/agent/imma_om_api.cc:6941 >> immsv_sync: remainingSpace 539 objsInBatch:129
<143>1 2018-05-28T11:59:06.745828+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6367"] 846:imm/agent/imma_om_api.cc:6482 >> get_obj_size
<143>1 2018-05-28T11:59:06.747585+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6386"] 846:imm/agent/imma_om_api.cc:6513 TR Object size: 454
<143>1 2018-05-28T11:59:06.747633+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6387"] 846:imm/agent/imma_om_api.cc:6515 << get_obj_size
<143>1 2018-05-28T11:59:06.747681+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6388"] 846:imm/agent/imma_om_api.cc:7094 TR Remaining space:85
<143>1 2018-05-28T11:59:06.747728+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6389"] 846:imm/agent/imma_om_api.cc:7117 << immsv_sync
<143>1 2018-05-28T11:59:06.747776+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6390"] 846:imm/immloadd/imm_loader.cc:2374 TR SA_AIS_ERR_NOT_READY => BUFFERED
<143>1 2018-05-28T11:59:06.747824+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6391"] 846:imm/immloadd/imm_loader.cc:2382 TR Synced object: safLgStrCfg=test_91,safLgStrCfg=test
<143>1 2018-05-28T11:59:06.748207+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6392"] 848:mds/mds_dt_trans.c:755 >> mdtm_process_poll_recv_data_tcp
<143>1 2018-05-28T11:59:06.748419+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6393"] 846:imm/agent/imma_om_api.cc:6941 >> immsv_sync: remainingSpace 85 objsInBatch:130
<143>1 2018-05-28T11:59:06.750146+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6411"] 846:imm/agent/imma_om_api.cc:6482 >> get_obj_size
<143>1 2018-05-28T11:59:06.752146+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6434"] 846:imm/agent/imma_om_api.cc:6513 TR Object size: 8606
<143>1 2018-05-28T11:59:06.752166+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6435"] 846:imm/agent/imma_om_api.cc:6515 << get_obj_size
<143>1 2018-05-28T11:59:06.752186+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6436"] 846:imm/agent/imma_om_api.cc:7094 TR Remaining space:-8521
<141>1 2018-05-28T11:59:06.752291+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6437"] 846:imm/agent/imma_om_api.cc:7160 NO >> immsv_sync
<143>1 2018-05-28T11:59:06.752815+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6438"] 846:imm/common/immsv_evt.c:1950 TR syncDepth > 20 :130
<141>1 2018-05-28T11:59:06.75295+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6439"] 846:imm/agent/imma_proc.cc:3565 NO imma_evt_fake_evs: size = 66187
<141>1 2018-05-28T11:59:06.757232+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6440"] 846:imm/agent/imma_om_api.cc:7162 NO << immsv_sync
<143>1 2018-05-28T11:59:06.757351+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6441"] 846:imm/agent/imma_om_api.cc:7220 << immsv_sync
<143>1 2018-05-28T11:59:06.757374+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6442"] 846:imm/immloadd/imm_loader.cc:2369 TR SA_AIS_OK => sync sent message
<143>1 2018-05-28T11:59:06.757394+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6443"] 846:imm/immloadd/imm_loader.cc:2382 TR Synced object: safLgStrCfg=test_911,safLgStrCfg=test
<143>1 2018-05-28T11:59:06.769784+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6444"] 848:mds/mds_dt_trans.c:755 >> mdtm_process_poll_recv_data_tcp
<143>1 2018-05-28T11:59:06.770035+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6445"] 846:imm/agent/imma_om_api.cc:8234 >> saImmOmSearchFinalize
<143>1 2018-05-28T11:59:06.770387+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6446"] 848:mds/mds_dt_trans.c:755 >> mdtm_process_poll_recv_data_tcp
<143>1 2018-05-28T11:59:06.77052+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6447"] 846:imm/agent/imma_om_api.cc:8401 << saImmOmSearchFinalize
<143>1 2018-05-28T11:59:06.770544+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6448"] 846:imm/immloadd/imm_loader.cc:2455 TR Synced 130 objects of class TestDb
<143>1 2018-05-28T11:59:06.770564+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6449"] 846:imm/immloadd/imm_loader.cc:2204 TR Syncing instances of class SaSmfSwBundle
<143>1 2018-05-28T11:59:06.770601+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6450"] 846:imm/immloadd/imm_loader.cc:2210 TR maxBatchSize set to 58680

Discussion

  • Vu Minh Nguyen

    Vu Minh Nguyen - 2018-05-28
    • Description has changed:

    Diff:

    --- old
+++ new
@@ -6,7 +6,7 @@

 > SC-1 osafimmd[xxx]: NO MDTM: Not possible to send size:65262 TIPC multicast to svc_id = IMMND(25)

-Here is osafimmloadd's syslog to show up the case:
+Here is osafimmloadd's trace to show up the case:

 > <143>1 2018-05-28T11:59:06.743861+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6348"] 846:imm/agent/imma_om_api.cc:7094 TR Remaining space:539
 > <143>1 2018-05-28T11:59:06.74391+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6349"] 846:imm/agent/imma_om_api.cc:7117 << immsv_sync
     

  • Vu Minh Nguyen

    Vu Minh Nguyen - 2018-05-28
    • Description has changed:

    Diff:

    --- old
+++ new
@@ -1,4 +1,4 @@
-During IMM sync, to speed up the sync progress, osafimmloadd packs a bunch of IMM class objects in one package and sends to IMMND coordinator in one go. The size of the package could be adjustable via the configurable attribute `opensafImmSyncBatchSize` which has the default value around 90% of `MDS_DIRECT_BUF_MAXSIZE`.
+To speed up IMM sync process, osafimmloadd packs a bunch of IMM class objects in one package and sends to IMMND coordinator in one go. The size of the package could be adjustable via the configurable attribute `opensafImmSyncBatchSize` which has the default value around 90% of `MDS_DIRECT_BUF_MAXSIZE`.

 With current code, objects will be pushed into the batch as long as the space which is 90% of `opensafImmSyncBatchSize` still remains - is larger than zero.
     

  • Gary Lee

    Gary Lee - 2018-06-29
    • Milestone: 5.18.06 --> 5.18.08
     

  • Gary Lee

    Gary Lee - 2018-09-29
    • Milestone: 5.18.09 --> 5.18.12
     

  • Gary Lee

    Gary Lee - 2019-01-09
    • Milestone: 5.19.01 --> 5.19.03
     

  • Gary Lee

    Gary Lee - 2019-03-26
    • Milestone: 5.19.03 --> 5.19.06
     

  • Gary Lee

    Gary Lee - 2019-07-23
    • Milestone: 5.19.07 --> 5.19.10
     

  • Gary Lee

    Gary Lee - 2019-10-21
    • Milestone: 5.19.10 --> 5.20.01
     

  • Gary Lee

    Gary Lee - 2020-02-15
    • Milestone: 5.20.02 --> 5.20.05
     

  • Gary Lee

    Gary Lee - 2020-05-30
    • Milestone: 5.20.05 --> 5.20.08
     

  • Gary Lee

    Gary Lee - 2020-08-31
    • Milestone: 5.20.08 --> 5.20.11
     

  • Gary Lee

    Gary Lee - 2020-12-01
    • Milestone: 5.20.11 --> 5.21.03
     

  • Gary Lee

    Gary Lee - 2021-03-01
    • Milestone: 5.21.03 --> 5.21.06
     

  • Surbhi Tripathi

    Surbhi Tripathi - 2021-04-12
    • assigned_to: Vu Minh Nguyen --> Surbhi Tripathi
     

  • Gary Lee

    Gary Lee - 2021-06-01
    • Milestone: 5.21.06 --> 5.21.10
     

  • Surbhi Tripathi

    Surbhi Tripathi - 2021-06-21

    From the logs can see no new object was added when the remaining size was not enough to accommodate new object:

    <143>1 2018-05-28T11:59:06.748419+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6393"] 846:imm/agent/imma_om_api.cc:6941 >> immsv_sync: remainingSpace 85 objsInBatch:130
    <143>1 2018-05-28T11:59:06.750146+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6411"] 846:imm/agent/imma_om_api.cc:6482 >> get_obj_size
    <143>1 2018-05-28T11:59:06.752146+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6434"] 846:imm/agent/imma_om_api.cc:6513 TR Object size: 8606
    <143>1 2018-05-28T11:59:06.752166+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6435"] 846:imm/agent/imma_om_api.cc:6515 << get_obj_size
    <143>1 2018-05-28T11:59:06.752186+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6436"] 846:imm/agent/imma_om_api.cc:7094 TR Remaining space:-8521
    <141>1 2018-05-28T11:59:06.752291+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6437"] 846:imm/agent/imma_om_api.cc:7160 NO >> immsv_sync
    <143>1 2018-05-28T11:59:06.752815+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6438"] 846:imm/common/immsv_evt.c:1950 TR syncDepth > 20 :130
    <141>1 2018-05-28T11:59:06.75295+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6439"] 846:imm/agent/imma_proc.cc:3565 NO imma_evt_fake_evs: size = 66187
    <141>1 2018-05-28T11:59:06.757232+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6440"] 846:imm/agent/imma_om_api.cc:7162 NO << immsv_sync
    <143>1 2018-05-28T11:59:06.757351+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6441"] 846:imm/agent/imma_om_api.cc:7220 << immsv_sync
    <143>1 2018-05-28T11:59:06.757374+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6442"] 846:imm/immloadd/imm_loader.cc:2369 TR SA_AIS_OK => sync sent message
    <143>1 2018-05-28T11:59:06.757394+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6443"] 846:imm/immloadd/imm_loader.cc:2382 TR Synced object: safLgStrCfg=test_911,safLgStrCfg=test
    <143>1 2018-05-28T11:59:06.769784+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6444"] 848:mds/mds_dt_trans.c:755 >> mdtm_process_poll_recv_data_tcp
    <143>1 2018-05-28T11:59:06.770035+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6445"] 846:imm/agent/imma_om_api.cc:8234 >> saImmOmSearchFinalize
    <143>1 2018-05-28T11:59:06.770387+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6446"] 848:mds/mds_dt_trans.c:755 >> mdtm_process_poll_recv_data_tcp
    <143>1 2018-05-28T11:59:06.77052+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6447"] 846:imm/agent/imma_om_api.cc:8401 << saImmOmSearchFinalize
    <143>1 2018-05-28T11:59:06.770544+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6448"] 846:imm/immloadd/imm_loader.cc:2455 TR Synced 130 objects of class TestDb
    <143>1 2018-05-28T11:59:06.770564+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6449"] 846:imm/immloadd/imm_loader.cc:2204 TR Syncing instances of class SaSmfSwBundle
    <143>1 2018-05-28T11:59:06.770601+07:00 SC-1 osafimmloadd 846 osafimmnd [meta sequenceId="6450"] 846:imm/immloadd/imm_loader.cc:2210 TR maxBatchSize set to 58680*

    130 objects are synced (and not 131). No new object was added. The size exceeding the MDS_DIRECT_BUF_MAXSIZE, is after encoding.

    SC-1 osafimmd[xxx]: NO MDTM: Not possible to send size:65262 TIPC multicast to svc_id = IMMND(25)

     

    • Surbhi Tripathi

      Surbhi Tripathi - 2021-07-27

      The increasing object count happen before calling function "immsv_sync". That's mean 130 already include current object not 131.

       

  • Surbhi Tripathi

    Surbhi Tripathi - 2021-06-22
    • status: assigned --> review
     

  • Surbhi Tripathi

    Surbhi Tripathi - 2021-07-27
    • status: review --> assigned
     

  • Surbhi Tripathi

    Surbhi Tripathi - 2021-07-27
    • assigned_to: Surbhi Tripathi --> Hieu Hong Hoang
     

  • Hieu Hong Hoang

    Hieu Hong Hoang - 2021-08-20

    When the package size is over MDS_DIRECT_BUF_MAXSIZE, dtm still send that packet successful. The reason is that dtm module support fragmentation for big packet. If the package size is over the maximum buffer size, that packet will be fragmented into smaller packets before send.

    <142>1 2021-08-17T11:17:30.552487+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8520"] MDTM: User Sending Data lenght=81100 From svc_id = IMMA_OM(26) to svc_id = IMMND(25)
<143>1 2021-08-17T11:17:30.55249+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8521"] MDTM: User fragment and Sending Data lenght=81100 From svc_id = IMMA_OM(26) to svc_id = IMMND(25)
<143>1 2021-08-17T11:17:30.552605+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8522"] MDTM:Sending message with Service Seqno=134, Fragment Seqnum=135, frag_num=32769, TO Dest_Tipc_id=<0x01001001:323663311>
<142>1 2021-08-17T11:17:30.552616+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8523"] MDTM: TIPC Sending Len=65262
<142>1 2021-08-17T11:17:30.552671+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8524"] MDTM: Successfully sent message
<143>1 2021-08-17T11:17:30.552691+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8525"] MDTM:Sending message with Service Seqno=134, Fragment Seqnum=135, frag_num=2, TO Dest_Tipc_id=<0x01001001:323663311>
<142>1 2021-08-17T11:17:30.552695+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8526"] MDTM: TIPC Sending Len=15887
<142>1 2021-08-17T11:17:30.5527+02:00 SC-1 osafimmnd 416 mds.log [meta sequenceId="195833"] MDTM: Data received: Processing data 
<142>1 2021-08-17T11:17:30.55271+02:00 SC-1 osafimmloadd 746 mds.log [meta sequenceId="8527"] MDTM: Successfully sent message

    We couldn't reproduce the below error. 

    SC-1 osafimmd[xxx]: NO MDTM: Not possible to send size:65262 TIPC multicast to svc_id = IMMND(25)

    Pushing object to batch is not good but it's acceptable. We will consider to improve it if it make any serious impact in the future.

     

  • Hieu Hong Hoang

    Hieu Hong Hoang - 2021-08-20
    • status: assigned --> not-reproducible
     

Log in to post a comment.