Re: [PATCH v2] migration: using trace_ to replace DPRINTF

[Bihong Yu]

OK, thank you for your help.

On 2020/10/20 15:18, Philippe Mathieu-Daudé wrote:
> On 10/20/20 9:07 AM, Bihong Yu wrote:
>>
>>
>> On 2020/10/20 14:54, Philippe Mathieu-Daudé wrote:
>>> On 10/20/20 8:42 AM, Bihong Yu wrote:
>>>> Signed-off-by: Bihong Yu <yubihong@huawei.com>
>>>> ---
>>>>    migration/block.c      | 36 ++++++++++++++++++------------------
>>>>    migration/page_cache.c | 13 +++----------
>>>>    migration/trace-events | 13 +++++++++++++
>>>>    3 files changed, 34 insertions(+), 28 deletions(-)
>>>>
>>>> diff --git a/migration/block.c b/migration/block.c
>>>> index 273392b..1e76a9f 100644
>>>> --- a/migration/block.c
>>>> +++ b/migration/block.c
>>>> @@ -26,6 +26,7 @@
>>>>    #include "qemu-file.h"
>>>>    #include "migration/vmstate.h"
>>>>    #include "sysemu/block-backend.h"
>>>> +#include "trace.h"
>>>>      #define BLK_MIG_BLOCK_SIZE           (1 << 20)
>>>>    #define BDRV_SECTORS_PER_DIRTY_CHUNK (BLK_MIG_BLOCK_SIZE >> 
>>>> BDRV_SECTOR_BITS)
>>>> @@ -434,10 +435,9 @@ static int init_blk_migration(QEMUFile *f)
>>>>            block_mig_state.total_sector_sum += sectors;
>>>>              if (bmds->shared_base) {
>>>> -            DPRINTF("Start migration for %s with shared base image\n",
>>>> -                    bdrv_get_device_name(bs));
>>>> +            trace_init_blk_migration_shared(bdrv_get_device_name(bs));
>>>>            } else {
>>>> -            DPRINTF("Start full migration for %s\n", 
>>>> bdrv_get_device_name(bs));
>>>> +            trace_init_blk_migration_full(bdrv_get_device_name(bs));
>>>>            }
>>>>              QSIMPLEQ_INSERT_TAIL(&block_mig_state.bmds_list, bmds, entry);
>>>> @@ -592,7 +592,7 @@ static int mig_save_device_dirty(QEMUFile *f, 
>>>> BlkMigDevState *bmds,
>>>>        return (bmds->cur_dirty >= bmds->total_sectors);
>>>>      error:
>>>> -    DPRINTF("Error reading sector %" PRId64 "\n", sector);
>>>> +    trace_mig_save_device_dirty(sector);
>>>>        g_free(blk->buf);
>>>>        g_free(blk);
>>>>        return ret;
>>>> @@ -628,9 +628,9 @@ static int flush_blks(QEMUFile *f)
>>>>        BlkMigBlock *blk;
>>>>        int ret = 0;
>>>>    -    DPRINTF("%s Enter submitted %d read_done %d transferred %d\n",
>>>> -            __func__, block_mig_state.submitted, 
>>>> block_mig_state.read_done,
>>>> -            block_mig_state.transferred);
>>>> +    trace_flush_blks("Enter", block_mig_state.submitted,
>>>> +                     block_mig_state.read_done,
>>>> +                     block_mig_state.transferred);
>>>>          blk_mig_lock();
>>>>        while ((blk = QSIMPLEQ_FIRST(&block_mig_state.blk_list)) != NULL) {
>>>> @@ -656,9 +656,9 @@ static int flush_blks(QEMUFile *f)
>>>>        }
>>>>        blk_mig_unlock();
>>>>    -    DPRINTF("%s Exit submitted %d read_done %d transferred %d\n", 
>>>> __func__,
>>>> -            block_mig_state.submitted, block_mig_state.read_done,
>>>> -            block_mig_state.transferred);
>>>> +    trace_flush_blks("Exit", block_mig_state.submitted,
>>>> +                     block_mig_state.read_done,
>>>> +                     block_mig_state.transferred);
>>>>        return ret;
>>>>    }
>>>>    @@ -727,8 +727,8 @@ static int block_save_setup(QEMUFile *f, void 
>>>> *opaque)
>>>>    {
>>>>        int ret;
>>>>    -    DPRINTF("Enter save live setup submitted %d transferred %d\n",
>>>> -            block_mig_state.submitted, block_mig_state.transferred);
>>>> +    trace_migration_block_save("setup", block_mig_state.submitted,
>>>> +                               block_mig_state.transferred);
>>>>          qemu_mutex_lock_iothread();
>>>>        ret = init_blk_migration(f);
>>>> @@ -759,8 +759,8 @@ static int block_save_iterate(QEMUFile *f, void 
>>>> *opaque)
>>>>        int64_t last_ftell = qemu_ftell(f);
>>>>        int64_t delta_ftell;
>>>>    -    DPRINTF("Enter save live iterate submitted %d transferred %d\n",
>>>> -            block_mig_state.submitted, block_mig_state.transferred);
>>>> +    trace_migration_block_save("iterate", block_mig_state.submitted,
>>>> +                               block_mig_state.transferred);
>>>>          ret = flush_blks(f);
>>>>        if (ret) {
>>>> @@ -825,8 +825,8 @@ static int block_save_complete(QEMUFile *f, void 
>>>> *opaque)
>>>>    {
>>>>        int ret;
>>>>    -    DPRINTF("Enter save live complete submitted %d transferred %d\n",
>>>> -            block_mig_state.submitted, block_mig_state.transferred);
>>>> +    trace_migration_block_save("complete", block_mig_state.submitted,
>>>> +                               block_mig_state.transferred);
>>>>          ret = flush_blks(f);
>>>>        if (ret) {
>>>> @@ -851,7 +851,7 @@ static int block_save_complete(QEMUFile *f, void 
>>>> *opaque)
>>>>        /* report completion */
>>>>        qemu_put_be64(f, (100 << BDRV_SECTOR_BITS) | BLK_MIG_FLAG_PROGRESS);
>>>>    -    DPRINTF("Block migration completed\n");
>>>> +    trace_migration_block_save_complete();
>>>>          qemu_put_be64(f, BLK_MIG_FLAG_EOS);
>>>>    @@ -884,7 +884,7 @@ static void block_save_pending(QEMUFile *f, void 
>>>> *opaque, uint64_t max_size,
>>>>            pending = max_size + BLK_MIG_BLOCK_SIZE;
>>>>        }
>>>>    -    DPRINTF("Enter save live pending  %" PRIu64 "\n", pending);
>>>> +    trace_migration_block_save_pending(pending);
>>>>        /* We don't do postcopy */
>>>>        *res_precopy_only += pending;
>>>>    }
>>>> diff --git a/migration/page_cache.c b/migration/page_cache.c
>>>> index 775582f..d554efa 100644
>>>> --- a/migration/page_cache.c
>>>> +++ b/migration/page_cache.c
>>>> @@ -18,14 +18,7 @@
>>>>    #include "qapi/error.h"
>>>>    #include "qemu/host-utils.h"
>>>>    #include "page_cache.h"
>>>> -
>>>> -#ifdef DEBUG_CACHE
>>>> -#define DPRINTF(fmt, ...) \
>>>> -    do { fprintf(stdout, "cache: " fmt, ## __VA_ARGS__); } while (0)
>>>> -#else
>>>> -#define DPRINTF(fmt, ...) \
>>>> -    do { } while (0)
>>>> -#endif
>>>> +#include "trace.h"
>>>>      /* the page in cache will not be replaced in two cycles */
>>>>    #define CACHED_PAGE_LIFETIME 2
>>>> @@ -75,7 +68,7 @@ PageCache *cache_init(int64_t new_size, size_t 
>>>> page_size, Error **errp)
>>>>        cache->num_items = 0;
>>>>        cache->max_num_items = num_pages;
>>>>    -    DPRINTF("Setting cache buckets to %" PRId64 "\n", 
>>>> cache->max_num_items);
>>>> +    trace_cache_init(cache->max_num_items);
>>>>          /* We prefer not to abort if there is no memory */
>>>>        cache->page_cache = g_try_malloc((cache->max_num_items) *
>>>> @@ -169,7 +162,7 @@ int cache_insert(PageCache *cache, uint64_t addr, 
>>>> const uint8_t *pdata,
>>>>        if (!it->it_data) {
>>>>            it->it_data = g_try_malloc(cache->page_size);
>>>>            if (!it->it_data) {
>>>> -            DPRINTF("Error allocating page\n");
>>>> +            trace_cache_insert();
>>>>                return -1;
>>>>            }
>>>>            cache->num_items++;
>>>> diff --git a/migration/trace-events b/migration/trace-events
>>>> index 338f38b..094dbe4 100644
>>>> --- a/migration/trace-events
>>>> +++ b/migration/trace-events
>>>> @@ -325,3 +325,16 @@ get_ramblock_vfn_hash(const char *idstr, uint64_t 
>>>> vfn, uint32_t crc) "ramblock n
>>>>    calc_page_dirty_rate(const char *idstr, uint32_t new_crc, uint32_t 
>>>> old_crc) "ramblock name: %s, new crc: %" PRIu32 ", old crc: %" PRIu32
>>>>    skip_sample_ramblock(const char *idstr, uint64_t ramblock_size) 
>>>> "ramblock name: %s, ramblock size: %" PRIu64
>>>>    find_page_matched(const char *idstr) "ramblock %s addr or size changed"
>>>> +
>>>> +# block.c
>>>> +init_blk_migration_shared(const char *blk_device_name) "Start migration 
>>>> for %s with shared base image"
>>>> +init_blk_migration_full(const char *blk_device_name) "Start full 
>>>> migration for %s"
>>>> +mig_save_device_dirty(int64_t sector) "Error reading sector %" PRId64
>>>> +flush_blks(const char *action, int submitted, int read_done, int 
>>>> transferred) "%s submitted %d read_done %d transferred %d"
>>>
>>> When using tracing, you usually start with a global pattern,
>>> then slowly remove events until tracing the particular one
>>> interesting you. As these all belong to the same subsystem,
>>> please use "migration_block_" prefix for all.
>>
>> All migration block file trace function need add "migration_block_"? Such as:
>> migration_block_init_blk_migration_shared()
> 
>   -> migration_block_init_shared
> 
>> migration_block_init_blk_migration_full()
> 
>   -> migration_block_init_full
> 
>> ...
>>
>>>
>>>> +migration_block_save(const char *mig_stage, int submitted, int 
>>>> transferred) "Enter save live %s submitted %d transferred %d"
>>>> +migration_block_save_complete(void) "Block migration completed"
>>>> +migration_block_save_pending(uint64_t pending) "Enter save live pending  
>>>> %" PRIu64
>>>
>>> These are good.
>>>
>>>> +
>>>> +# page_cache.c
>>>> +cache_init(int64_t max_num_items) "Setting cache buckets to %" PRId64
>>>> +cache_insert(void) "Error allocating page"
>>>
>>> Please use "migration_block_" prefix here too.
>>
>> Do you mean using "migration_" prefix? Such as:
>> migration_cache_init()
>> migration_cache_insert()
>> ...
> 
> Yes ;) Or even:
> 
>  - migration_pagecache_init
>  - migration_pagecache_insert
> 
>>
>>>
>>> Regards,
>>>
>>> Phil.
>>>
>>> .
>>
> 
> .