improve debug messages

Author: bratpiorka

src/provider/provider_tracking.c

@@ -7,24 +7,26 @@
  *
  */
 
-#include "provider_tracking.h"
+#include <assert.h>
+#include <errno.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include <umf/memory_pool.h>
+#include <umf/memory_provider.h>
+#include <umf/memory_provider_ops.h>
+
 #include "base_alloc_global.h"
 #include "critnib.h"
 #include "ipc_internal.h"
+#include "libumf.h"
+#include "memory_pool_internal.h"
+#include "provider_tracking.h"
 #include "utils_common.h"
 #include "utils_concurrency.h"
 #include "utils_log.h"
 
-#include <umf/memory_pool.h>
-#include <umf/memory_provider.h>
-#include <umf/memory_provider_ops.h>
-
-#include <assert.h>
-#include <errno.h>
-#include <stdio.h>
-#include <stdlib.h>
-#include <string.h>
-
 typedef struct tracker_value_t {
     umf_memory_pool_handle_t pool;
     size_t size;
@@ -82,9 +84,8 @@ static umf_result_t umfMemoryTrackerRemove(umf_memory_tracker_handle_t hTracker,
     }
 
     tracker_value_t *v = value;
-
-    LOG_DEBUG("memory region removed: tracker=%p, ptr=%p, size=%zu",
-              (void *)hTracker, ptr, v->size);
+    LOG_DEBUG("memory region removed: tracker=%p, ptr=%p, pool=%p, size=%zu",
+              (void *)hTracker, ptr, (void *)v->pool, v->size);
 
     umf_ba_free(hTracker->tracker_allocator, value);
 
@@ -167,22 +168,25 @@ static umf_result_t trackingAlloc(void *hProvider, size_t size,
         return ret;
     }
 
+    LOG_DEBUG("allocated %p, provider: %p, size: %zu", *ptr,
+              (void *)p->hUpstream, size);
+
     // check if the allocation was already added to the tracker
     tracker_value_t *value =
         (tracker_value_t *)critnib_get(p->hTracker->map, *(uintptr_t *)ptr);
     if (value) {
         assert(value->pool != p->pool);
+        LOG_ERR("ptr already exists in the tracker ptr=%p, old size=%zu, new "
+                "size=%zu, old pool %p, new pool %p, tracker %p",
+                *ptr, value->size, size, (void *)value->pool, (void *)p->pool,
+                (void *)p->hTracker);
 
-        LOG_DEBUG("ptr already exists in the tracker (added by Proxy Lib) - "
-                  "updating value, ptr=%p, size=%zu, old pool: %p, new pool %p",
-                  *ptr, size, (void *)value->pool, (void *)p->pool);
-
-        // the allocation was made by the ProxyLib so we only update the tracker
         value->pool = p->pool;
+        value->size = size;
         int crit_ret = critnib_insert(p->hTracker->map, *(uintptr_t *)ptr,
                                       value, 1 /* update */);
 
-        // this cannot fail since we know the element exists  and there is
+        // this cannot fail since we know the element exists and there is
         // nothing to allocate
         assert(crit_ret == 0);
         (void)crit_ret;
@@ -221,6 +225,12 @@ static umf_result_t trackingAllocationSplit(void *hProvider, void *ptr,
         goto err_lock;
     }
 
+    void *highPtr = (void *)(((uintptr_t)ptr) + firstSize);
+    size_t secondSize = totalSize - firstSize;
+
+    LOG_DEBUG("trying to split (%p, %zu) to (%p, %zu) and (%p, %zu)", ptr,
+              totalSize, ptr, firstSize, highPtr, secondSize);
+
     tracker_value_t *value =
         (tracker_value_t *)critnib_get(provider->hTracker->map, (uintptr_t)ptr);
     if (!value) {
@@ -242,9 +252,6 @@ static umf_result_t trackingAllocationSplit(void *hProvider, void *ptr,
         goto err;
     }
 
-    void *highPtr = (void *)(((uintptr_t)ptr) + firstSize);
-    size_t secondSize = totalSize - firstSize;
-
     // We'll have a duplicate entry for the range [highPtr, highValue->size] but this is fine,
     // the value is the same anyway and we forbid removing that range concurrently
     ret = umfMemoryTrackerAdd(provider->hTracker, provider->pool, highPtr,
@@ -259,6 +266,9 @@ static umf_result_t trackingAllocationSplit(void *hProvider, void *ptr,
         goto err;
     }
 
+    LOG_DEBUG("update split region ptr=%p, pool=%p size=%zu", ptr,
+              (void *)splitValue->pool, splitValue->size);
+
     int cret = critnib_insert(provider->hTracker->map, (uintptr_t)ptr,
                               (void *)splitValue, 1 /* update */);
     // this cannot fail since we know the element exists (nothing to allocate)
@@ -302,22 +312,26 @@ static umf_result_t trackingAllocationMerge(void *hProvider, void *lowPtr,
     tracker_value_t *lowValue = (tracker_value_t *)critnib_get(
         provider->hTracker->map, (uintptr_t)lowPtr);
     if (!lowValue) {
-        LOG_ERR("no left value");
+        LOG_ERR("no left value (%p) found in tracker!", lowPtr);
         ret = UMF_RESULT_ERROR_INVALID_ARGUMENT;
         goto err;
     }
+
     tracker_value_t *highValue = (tracker_value_t *)critnib_get(
         provider->hTracker->map, (uintptr_t)highPtr);
     if (!highValue) {
-        LOG_ERR("no right value");
+        LOG_ERR("no right value (%p) found in tracker!", highPtr);
         ret = UMF_RESULT_ERROR_INVALID_ARGUMENT;
         goto err;
     }
+
     if (lowValue->pool != highValue->pool) {
-        LOG_ERR("pool mismatch");
+        LOG_ERR("pool mismatch: %p vs %p", (void *)lowValue->pool,
+                (void *)highValue->pool);
         ret = UMF_RESULT_ERROR_INVALID_ARGUMENT;
         goto err;
     }
+
     if (lowValue->size + highValue->size != totalSize) {
         LOG_ERR("lowValue->size + highValue->size != totalSize");
         ret = UMF_RESULT_ERROR_INVALID_ARGUMENT;
@@ -354,6 +368,8 @@ static umf_result_t trackingAllocationMerge(void *hProvider, void *lowPtr,
 
 err:
     utils_mutex_unlock(&provider->hTracker->splitMergeMutex);
+    assert(0);
+
 err_lock:
     umf_ba_free(provider->hTracker->tracker_allocator, mergedValue);
     return ret;
@@ -375,7 +391,7 @@ static umf_result_t trackingFree(void *hProvider, void *ptr, size_t size) {
             // DO NOT return an error here, because the tracking provider
             // cannot change behaviour of the upstream provider.
             LOG_ERR("failed to remove the region from the tracker, ptr=%p, "
-                    "size=%zu, ret = %d",
+                    "size=%zu, ret=%d",
                     ptr, size, ret_remove);
         }
     }