Matter PacketBuffer Pool Empty due to Large Pre-Allocation I am working on a Matter device FRDM-RW612. I noticed that sometimes that PacketBuffer pool runs empty. I have attached the log here [29889] [INFO] [IN] CASE Server received Sigma1 message . Starting handshake. EC 0x2005cd68
[29898] [INFO] [SC] Received Sigma1 msg
[29901] [TRACE] [SC] Found MRP parameters in the message
[29907] [TRACE] [SC] Peer assigned session key ID 582
[29912] [INFO] [DL] KVS, get key id:: f/1/g
[29916] [INFO] [DL] KVS, get key id:: f/1/k/0
[29922] [INFO] [SC] CASE matched destination ID: fabricIndex 1, NodeID 0x00000000000022B8
[30054] [INFO] [CSL] LWIP:PacketBuffer::New Request size=870, aAvailable=758, aReserved=112, MaxSize=64000
[30064] [INFO] [EM] <<< [E:14060r S:0 M:111174838] (U) Msg TX from 0000000000000000 to 0:0ED014D28E28AE99 [0000] [TCP:[FE80::FE84:A7FF:FE51:F90A]:40004] --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:748)
[30083] [INFO] [SC] Sent Sigma2 msg
[30087] [ERR] [DL] Long dispatch time: 219 ms, for event type 3
[30092] [TRACE] [DL] DeviceEventCallback: 0x8016
[30214] [INFO] [EM] >>> [E:14060r S:0 M:239333775] (U) Msg RX from 0:0ED014D28E28AE99 [0000] to 0000000000000000 --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:594)
[30229] [TRACE] [EM] Found matching exchange: 14060r, Delegate: 0x2005bd74
[30236] [INFO] [SC] Received Sigma3 msg
[30288] [INFO] [DL] KVS, get key id:: g/sri
[30293] [ERR] [DL] KVS, key not found!
[30296] [INFO] [DL] KVS, put key id:: f/1/s/000000000001B669
[30304] [INFO] [DL] KVS, put key id:: g/s/HuzH83xHX2H4MZ6LiDY1cw==
[30312] [INFO] [DL] KVS, put key id:: g/sri
[30318] [TRACE] [SC] Sending status report. Protocol code 0, exchange 14060
[30325] [INFO] [CSL] LWIP:PacketBuffer::New Request size=120, aAvailable=8, aReserved=112, MaxSize=64000
[30334] [INFO] [EM] <<< [E:14060r S:0 M:111174839] (U) Msg TX from 0000000000000000 to 0:0ED014D28E28AE99 [0000] [TCP:[FE80::FE84:A7FF:FE51:F90A]:40004] --- Type 0000:40 (SecureChannel:StatusReport) (B:30)
[30354] [INFO] [SC] SecureSession[0x2005af10, LSID:25190]: State change 'kEstablishing' --> 'kActive'
[30363] [TRACE] [IN] SecureSession[0x2005af10]: Activated - Type:2 LSID:25190
[30371] [TRACE] [IN] New secure session activated for device <000000000001B669, 1>, LSID:25190 PSID:582!
[30380] [INFO] [IN] CASE Session established to peer: <000000000001B669, 1>
[30387] [TRACE] [IN] SecureSession[0x2005aff0]: Allocated Type:2 LSID:25191
[30394] [TRACE] [SC] Allocated SecureSession (0x2005aff0) - waiting for Sigma1 msg
[30402] [ERR] [DL] Long dispatch time: 114 ms, for event type 2
[30408] [INFO] [CSL] LWIP:PacketBuffer::New Request size=163, aAvailable=51, aReserved=112, MaxSize=64000
[30418] [INFO] [EM] >>> [E:14061r S:25190 M:250050934] (S) Msg RX from 1:000000000001B669 [578C] to 00000000000022B8 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
[30433] [TRACE] [EM] Handling via exchange: 14061r, Delegate: 0x2005723c
[30440] [TRACE] [DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[30449] [INFO] [FS] GeneralCommissioning: Received CommissioningComplete
[30455] [INFO] [DL] KVS, put key id:: g/fs/c
[30461] [INFO] [DL] KVS, put key id:: f/1/m
[30467] [INFO] [FP] Metadata for Fabric 0x1 persisted to storage.
[30473] [INFO] [DL] KVS, put key id:: f/1/o
[30479] [INFO] [DL] KVS, put key id:: f/1/n
[30485] [INFO] [DL] KVS, put key id:: f/1/i
[30492] [INFO] [DL] KVS, put key id:: f/1/r
[30498] [INFO] [TS] Committing Last Known Good Time to storage: 2024-08-17T05:19:27
[30506] [INFO] [DL] KVS, put key id:: g/lkgt
[30510] [INFO] [DL] KVS, put key id:: g/fidx
[30516] [INFO] [ZCL] OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x51EB0A41B403578C, FabricId 0000000000000001, NodeId 00000000000022B8, VendorId 0xFFF1
[30532] [INFO] [DL] KVS, deleting key id:: g/fs/c
[30538] [INFO] [FS] GeneralCommissioning: Successfully commited pending fabric data
[30545] [INFO] [FS] Fail-safe cleanly disarmed
[30550] [TRACE] [DMG] Endpoint 0, Cluster 0x0000_0030 update version to e5eec16d
[30557] [INFO] [DL] endpointId 0x0000_0000 clusterId 0x0000_0030 attribute ID: 0x0000_0000 Type: 39 Value: 0, length 8
[30568] [INFO] [CSL] LWIP:PacketBuffer::New Request size=63940, aAvailable=63828, aReserved=112, MaxSize=64000
[30578] [ERR] [CSL] PacketBuffer: pool EMPTY.
[30582] [ERR] [DMG] Adding response failed: b. Returning failure instead.
[30590] [ERR] [DMG] Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004 status 0x01 (no additional context)
[30599] [INFO] [CSL] LWIP:PacketBuffer::New Request size=63940, aAvailable=63828, aReserved=112, MaxSize=64000
[30609] [ERR] [CSL] PacketBuffer: pool EMPTY.
[30614] [ERR] [DMG] Failed to add command status: b
[30619] [TRACE] [DMG] Decreasing reference count for CommandHandlerImpl, remaining 1
[30626] [TRACE] [DMG] Decreasing reference count for CommandHandlerImpl, remaining 0
[30634] [ERR] [DMG] Failed to finalize command response: 3
[30640] [TRACE] [DMG] Command handler moving to [AwaitingDe]
[30645] [ERR] [DMG] Failed to send InvokeResponseMessage
[30650] [TRACE] [DMG] Command response sender moving to [AllInvokeR]
[30657] [ERR] [DL] Long dispatch time: 249 ms, for event type 3
[30663] [TRACE] [DL] DeviceEventCallback: 0x8018
[30667] [INFO] [SVR] Commissioning completed successfully
[30673] [INFO] [DIS] Updating services using commissioning mode 0
[30679] [INFO] [DIS] CHIP minimal mDNS started advertising.
[30685] [INFO] [CSL] LWIP:PacketBuffer::New Request size=624, aAvailable=512, aReserved=112, MaxSize=64000
[30695] [INFO] [CSL] LWIP:PacketBuffer::New Request size=1536, aAvailable=1424, aReserved=112, MaxSize=64000
[30705] [INFO] [CSL] LWIP:PacketBuffer::New Request size=624, aAvailable=512, aReserved=112, MaxSize=64000
[30716] [INFO] [CSL] LWIP:PacketBuffer::New Request size=1536, aAvailable=1424, aReserved=112, MaxSize=64000
[30726] [INFO] [CSL] LWIP:PacketBuffer::New Request size=624, aAvailable=512, aReserved=112, MaxSize=64000
[30736] [INFO] [CSL] LWIP:PacketBuffer::New Request size=1536, aAvailable=1424, aReserved=112, MaxSize=64000
[30746] [INFO] [CSL] LWIP:PacketBuffer::New Request size=624, aAvailable=512, aReserved=112, MaxSize=64000
[30757] [INFO] [CSL] LWIP:PacketBuffer::New Request size=1536, aAvailable=1424, aReserved=112, MaxSize=64000
[30767] [TRACE] [DL] Using WiFi MAC for hostname
[30772] [INFO] [DIS] Advertise operational node 51EB0A41B403578C-00000000000022B8
[30779] [TRACE] [DIS] Responding with _matter._tcp.local
[30784] [TRACE] [DIS] Responding with 51EB0A41B403578C-00000000000022B8._matter._tcp.local
[30793] [TRACE] [DIS] Responding with 51EB0A41B403578C-00000000000022B8._matter._tcp.local
[30801] [TRACE] [DIS] Responding with C095DA0152EF.local
[30806] [TRACE] [DIS] Responding with C095DA0152EF.local
[30812] [TRACE] [DIS] Responding with _I51EB0A41B403578C._sub._matter._tcp.local
[30819] [INFO] [DIS] CHIP minimal mDNS configured as 'Operational device'; instance name: 51EB0A41B403578C-00000000000022B8.
[30830] [INFO] [CSL] LWIP:PacketBuffer::New Request size=624, aAvailable=512, aReserved=112, MaxSize=64000
[30841] [INFO] [CSL] LWIP:PacketBuffer::New Request size=1536, aAvailable=1424, aReserved=112, MaxSize=64000
[30851] [INFO] [CSL] LWIP:PacketBuffer::New Request size=624, aAvailable=512, aReserved=112, MaxSize=64000
[30861] [INFO] [CSL] LWIP:PacketBuffer::New Request size=1536, aAvailable=1424, aReserved=112, MaxSize=64000
[30871] [INFO] [DIS] mDNS service published: _matter._tcp
[30877] [TRACE] [DL] CHIPoBLE advertising set to off
[30882] [TRACE] [IN] Expiring all PASE sessions
[30886] [TRACE] [IN] SecureSession[0x2005ae30]: MarkForEviction Type:1 LSID:25189
[30894] [INFO] [SC] SecureSession[0x2005ae30, LSID:25189]: State change 'kActive' --> 'kPendingEviction'
[30903] [TRACE] [IN] SecureSession[0x2005ae30]: Released - Type:1 LSID:25189
[30910] [TRACE] [IN] Clearing BLE pending packets.
[30915] [INFO] [BLE] Releasing end point's BLE connection back to application.
[30922] [INFO] [DL] Closing BLE GATT connection (ConnId 00)
[30930] [TRACE] [ZCL] Commissioning complete, notify platform driver to persist network credentials.
[30939] [INFO] [DL] KVS, put key id:: wifi-ssid
[30944] [INFO] [DL] KVS, put key id:: wifi-pass
[30948] [TRACE] [DL] DeviceEventCallback: 0x800f
[30953] [ERR] [DL] Long dispatch time: 286 ms, for event type 32783
[30988] [INFO] [DL] Current number of connections: 0/1
[30993] [INFO] [DL] BLE GAP connection terminated (reason 0x16)
[30999] [TRACE] [BLE] No endpoint for connection error
[31004] [TRACE] [DL] DeviceEventCallback: 0x8007 Here is the main part to focus: [30418] [INFO] [EM] >>> [E:14061r S:25190 M:250050934] (S) Msg RX from 1:000000000001B669 [578C] to 00000000000022B8 --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
[30433] [TRACE] [EM] Handling via exchange: 14061r, Delegate: 0x2005723c
[30440] [TRACE] [DMG] Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0004
[30449] [INFO] [FS] GeneralCommissioning: Received CommissioningComplete
[30455] [INFO] [DL] KVS, put key id:: g/fs/c
[30461] [INFO] [DL] KVS, put key id:: f/1/m
[30467] [INFO] [FP] Metadata for Fabric 0x1 persisted to storage.
[30473] [INFO] [DL] KVS, put key id:: f/1/o
[30479] [INFO] [DL] KVS, put key id:: f/1/n
[30485] [INFO] [DL] KVS, put key id:: f/1/i
[30492] [INFO] [DL] KVS, put key id:: f/1/r
[30498] [INFO] [TS] Committing Last Known Good Time to storage: 2024-08-17T05:19:27
[30506] [INFO] [DL] KVS, put key id:: g/lkgt
[30510] [INFO] [DL] KVS, put key id:: g/fidx
[30516] [INFO] [ZCL] OpCreds: Fabric index 0x1 was committed to storage. Compressed Fabric Id 0x51EB0A41B403578C, FabricId 0000000000000001, NodeId 00000000000022B8, VendorId 0xFFF1
[30532] [INFO] [DL] KVS, deleting key id:: g/fs/c
[30538] [INFO] [FS] GeneralCommissioning: Successfully commited pending fabric data
[30545] [INFO] [FS] Fail-safe cleanly disarmed
[30550] [TRACE] [DMG] Endpoint 0, Cluster 0x0000_0030 update version to e5eec16d
[30557] [INFO] [DL] endpointId 0x0000_0000 clusterId 0x0000_0030 attribute ID: 0x0000_0000 Type: 39 Value: 0, length 8
[30568] [INFO] [CSL] LWIP:PacketBuffer::New Request size=63940, aAvailable=63828, aReserved=112, MaxSize=64000
[30578] [ERR] [CSL] PacketBuffer: pool EMPTY.
[30582] [ERR] [DMG] Adding response failed: b. Returning failure instead. the actual message that is received, InvokeCommandResponse is of 59 bytes, or may be a CommissioningComplete command. But why almost 64KB is a pre-allocation requirement here? I have also added the PacketBuffer::New function here for tracing PacketBufferHandle PacketBufferHandle::New(size_t aAvailableSize, uint16_t aReservedSize)
{
// Sanity check for kStructureSize to ensure that it matches the PacketBuffer size.
static_assert(PacketBuffer::kStructureSize == sizeof(PacketBuffer), "PacketBuffer size mismatch");
// Setting a static upper bound on kStructureSize to ensure the summation of all the sizes does not overflow.
static_assert(PacketBuffer::kStructureSize <= UINT16_MAX, "kStructureSize should not exceed UINT16_MAX.");
// Setting a static upper bound on the maximum buffer size allocation for regular sized messages (not large).
static_assert(PacketBuffer::kMaxSizeWithoutReserve <= UINT16_MAX, "kMaxSizeWithoutReserve should not exceed UINT16_MAX.");
#if INET_CONFIG_ENABLE_TCP_ENDPOINT
// Setting a static upper bound on the maximum buffer size allocation for
// large messages.
#if CHIP_SYSTEM_CONFIG_USE_LWIP
// LwIP based systems are internally limited to using a u16_t type as the size of a buffer.
static_assert(PacketBuffer::kLargeBufMaxSizeWithoutReserve <= UINT16_MAX,
"In LwIP, max size for Large payload buffers cannot exceed UINT16_MAX!");
#else
// Messages over TCP are framed using a length field that is 32 bits in
// length.
static_assert(PacketBuffer::kLargeBufMaxSizeWithoutReserve <= UINT32_MAX,
"Max size for Large payload buffers cannot exceed UINT32_MAX");
#endif // CHIP_SYSTEM_CONFIG_USE_LWIP
#endif // INET_CONFIG_ENABLE_TCP_ENDPOINT
// Ensure that aAvailableSize is bound within a max and is not big enough to cause overflow during
// subsequent addition of all the sizes.
if (aAvailableSize > UINT32_MAX)
{
ChipLogError(chipSystemLayer,
"PacketBuffer: AvailableSize of a buffer cannot exceed UINT32_MAX. aAvailableSize = 0x" ChipLogFormatX64,
ChipLogValueX64(static_cast (aAvailableSize)));
return PacketBufferHandle();
}
// Cast all to uint64_t and add. This cannot overflow because we have
// ensured that the maximal value of the summation is
// UINT32_MAX + UINT16_MAX + UINT16_MAX, which should always fit in
// a uint64_t variable.
uint64_t sumOfSizes = static_cast (aAvailableSize) + static_cast (aReservedSize) +
static_cast (PacketBuffer::kStructureSize);
uint64_t sumOfAvailAndReserved = static_cast (aAvailableSize) + static_cast (aReservedSize);
// Ensure that the sum fits in a size_t so that casting into size_t variables,
// viz., lBlockSize and lAllocSize, is safe.
if (!CanCastTo (sumOfSizes))
{
ChipLogError(chipSystemLayer,
"PacketBuffer: Sizes of allocation request are invalid. (aAvailableSize = " ChipLogFormatX64
", aReservedSize = " ChipLogFormatX64 ")",
ChipLogValueX64(static_cast (aAvailableSize)), ChipLogValueX64(static_cast (aReservedSize)));
return PacketBufferHandle();
}
#if CHIP_SYSTEM_CONFIG_USE_LWIP
// LwIP based APIs have a maximum buffer size of UINT16_MAX. Ensure that
// limit is met during allocation.
if (sumOfAvailAndReserved > UINT16_MAX)
{
ChipLogError(chipSystemLayer,
"LwIP based systems require total buffer size to be less than UINT16_MAX!"
"Attempted allocation size = " ChipLogFormatX64,
ChipLogValueX64(sumOfAvailAndReserved));
return PacketBufferHandle();
}
#endif // CHIP_SYSTEM_CONFIG_USE_LWIP
// sumOfAvailAndReserved is no larger than sumOfSizes, which we checked can be cast to
// size_t.
const size_t lAllocSize = static_cast (sumOfAvailAndReserved);
PacketBuffer * lPacket;
CHIP_SYSTEM_FAULT_INJECT(FaultInjection::kFault_PacketBufferNew, return PacketBufferHandle());
if (lAllocSize > PacketBuffer::kMaxAllocSize)
{
ChipLogError(chipSystemLayer, "PacketBuffer: allocation exceeding buffer capacity limits: %lu > %lu",
static_cast (lAllocSize), static_cast (PacketBuffer::kMaxAllocSize));
return PacketBufferHandle();
}
#if CHIP_SYSTEM_CONFIG_USE_LWIP
// This cast is safe because lAllocSize is no larger than
// kMaxSizeWithoutReserve, which fits in uint16_t.
lPacket = static_cast (
pbuf_alloc(PBUF_RAW, static_cast (lAllocSize), CHIP_SYSTEM_PACKETBUFFER_LWIP_PBUF_TYPE));
SYSTEM_STATS_UPDATE_LWIP_PBUF_COUNTS();
ChipLogProgress(chipSystemLayer,"LWIP:PacketBuffer::New Request size=%u, aAvailable=%u, aReserved=%u, MaxSize=%u",lAllocSize,aAvailableSize,aReservedSize,PacketBuffer::kMaxAllocSize);
#elif CHIP_SYSTEM_PACKETBUFFER_FROM_CHIP_POOL
#if !CHIP_SYSTEM_CONFIG_NO_LOCKING && CHIP_SYSTEM_CONFIG_FREERTOS_LOCKING
if (!sBufferPoolMutex.isInitialized())
{
Mutex::Init(sBufferPoolMutex);
}
#endif
LOCK_BUF_POOL();
lPacket = PacketBuffer::sFreeList;
if (lPacket != nullptr)
{
PacketBuffer::sFreeList = lPacket->ChainedBuffer();
SYSTEM_STATS_INCREMENT(chip::System::Stats::kSystemLayer_NumPacketBufs);
}
UNLOCK_BUF_POOL();
ChipLogProgress(chipSystemLayer,"CHIP POOL:PacketBuffer::New Request size=%u",lAllocSize);
#elif CHIP_SYSTEM_PACKETBUFFER_FROM_CHIP_HEAP
// sumOfSizes is essentially (kStructureSize + lAllocSize) which we already
// checked to fit in a size_t.
const size_t lBlockSize = static_cast (sumOfSizes);
lPacket = reinterpret_cast (chip::Platform::MemoryAlloc(lBlockSize));
SYSTEM_STATS_INCREMENT(chip::System::Stats::kSystemLayer_NumPacketBufs);
ChipLogProgress(chipSystemLayer,"CHIP HEAP:PacketBuffer::New Request size=%u",lAllocSize);
#else
#error "Unimplemented PacketBuffer storage case"
#endif
if (lPacket == nullptr)
{
ChipLogError(chipSystemLayer, "PacketBuffer: pool EMPTY.");
return PacketBufferHandle();
}
lPacket->payload = lPacket->ReserveStart() + aReservedSize;
lPacket->len = lPacket->tot_len = 0;
lPacket->next = nullptr;
lPacket->ref = 1;
#if CHIP_SYSTEM_PACKETBUFFER_FROM_CHIP_HEAP
lPacket->alloc_size = lAllocSize;
#endif
return PacketBufferHandle(lPacket);
} Re: Matter PacketBuffer Pool Empty due to Large Pre-Allocation The example is all-clusters-app Re: Matter PacketBuffer Pool Empty due to Large Pre-Allocation I hope you are doing well too. The setup is on Ubuntu 22.04, with GN+Ninja build I followed the following commands ~ git clone https://github.com/NXP/matter.git
~ cd matter
~ scripts/checkout_submodules.py --shallow --platform nxp --recursive
~ source ./scripts/activate.sh
~ ./third_party/nxp/nxp_matter_support/scripts/update_nxp_sdk.py --platform common
~ git submodule update --init --recursive
~ source ./scripts/activate.sh
~ cd examples/all-clusters-app/nxp/rt/rw61x
~ gn gen --args="chip_enable_wifi=true chip_inet_config_enable_tcp_endpoint=true board_version=\"frdm\"" out/debug
~ ninja -C out/debug The matter version is release/v1.4.0, the default one. I am testing the chip-tool for large payload with chip-tool onoff on --allow-large-payload true [30568] [INFO] [CSL] LWIP:PacketBuffer::New Request size=63940, aAvailable=63828, aReserved=112, MaxSize=64000
[30578] [ERR] [CSL] PacketBuffer: pool EMPTY.
[30582] [ERR] [DMG] Adding response failed: b. Returning failure instead. The issue was within matter/src/app/CommandHandlerImpl.cpp. As in the below lines of code const size_t commandBufferMaxSize = mpResponder->GetCommandResponseMaxBufferSize();
auto commandPacket = System::PacketBufferHandle::New(commandBufferMaxSize);
VerifyOrReturnError(!commandPacket.IsNull(), CHIP_ERROR_NO_MEMORY); The mpResponder->GetCommandResponseMaxBufferSize() always returns around 63,940 bytes, and this PacketBuffer is used in both functions InvokeResponse and PrepareStatus within the same .cpp file. To solve this, I changed CHIP_SYSTEM_CONFIG_MAX_LARGE_BUFFER_SIZE_BYTES from 64 KB to 10 KB in matter/src/system/SystemConfig.h, since my messages never exceed 10 KB. However, allocating a PacketBuffer of the maximum size for sending a status report or InvokeResponse is still an overestimation. Re: Matter PacketBuffer Pool Empty due to Large Pre-Allocation Hello @farazahmed8, hope you are doing well.
In order to try to recreate your issue, could you please share your Matter and SDK release version as well as the example that you are working with? Also please confirm if you are using the MCUXpresso VS Code extension or with the GN/Ninja build on Linux.
記事全体を表示