{"id":1655,"date":"2025-08-06T06:23:01","date_gmt":"2025-08-06T06:23:01","guid":{"rendered":"https:\/\/craftcookcode.com\/?p=1655"},"modified":"2025-08-07T00:42:32","modified_gmt":"2025-08-07T00:42:32","slug":"qlik-replicate-stripping-latency-out-of-log-files","status":"publish","type":"post","link":"https:\/\/craftcookcode.com\/?p=1655","title":{"rendered":"Qlik Replicate: Stripping latency out of log files"},"content":{"rendered":"\n

We have been doing a bit of “Stress and Volume” testing in Qlik Replicate over the past few days; investigating how my latency is introduced to a MS SQL server task if we run it through a log stream.<\/p>\n\n\n\n

If you’re not aware – you can get minute latecy from Qlik Replicate by turning the “Performance” logs up to “Trace” or higher:<\/p>\n\n\n\n

\"\"<\/figure>\n\n\n\n

This will result in messages getting produced in the task’s log file like:<\/p>\n\n\n

\n00011044: 2025-08-04T14:57:56 [PERFORMANCE     ]T:  Source latency 1.23 seconds, Target latency 2.42 seconds, Handling latency 1.19 seconds  (replicationtask.c:3879)\n00011044: 2025-08-04T14:58:26 [PERFORMANCE     ]T:  Source latency 1.10 seconds, Target latency 2.27 seconds, Handling latency 1.16 seconds  (replicationtask.c:3879)\n00009024: 2025-08-04T14:58:30 [SOURCE_CAPTURE  ]I:  Throughput monitor: Last DB time scanned: 2025-08-04T14:58:30.700. Last LSN scanned: 008050a1:00002ce8:0004. #scanned events: 492815.   (sqlserver_log_utils.c:5000)\n00011044: 2025-08-04T14:58:57 [PERFORMANCE     ]T:  Source latency 0.61 seconds, Target latency 1.87 seconds, Handling latency 1.25 seconds  (replicationtask.c:3879)\n00011044: 2025-08-04T14:59:27 [PERFORMANCE     ]T:  Source latency 1.10 seconds, Target latency 1.55 seconds, Handling latency 0.45 seconds  (replicationtask.c:3879)\n\n<\/pre><\/div>\n\n\n
I created a simple python script to parse a folder of log files and output it in a excel.  Since the data ends up in a panda data frame; it would be easy to manipulate the data and output it in a specific way:<\/p>\n\n\n
\nimport os\nimport pandas as pd\nfrom datetime import datetime\n\n\ndef strip_seconds(inString):\n    \n    index = inString.find(" ")  \n    returnString = float(inString[0:index])\n    return(returnString)\n\n\ndef format_timestamp(in_timestamp):\n    \n    # Capture dates like "2025-08-01T10:42:36" and add a microsecond section\n    if len(in_timestamp) == 19:\n        in_timestamp = in_timestamp + ":000000"\n\n    date_format = "%Y-%m-%dT%H:%M:%S:%f"\n\n    # Converts date string to a date object    \n    date_obj = datetime.strptime(in_timestamp, date_format)\n\n    return date_obj\n\n        \ndef process_file(in_file_path):\n\n    return_array = []\n    \n    with open(in_file_path, "r") as in_file:\n    \n        for line in in_file:\n\n            upper_case = line.upper().strip()\n\n            if upper_case.find('[PERFORMANCE     ]') >= 0:\n                timestamp_temp = upper_case[10:37]\n                timestamp = timestamp_temp.split(" ")[0]\n                \n                split_string = upper_case.split("LATENCY ")\n                \n                if len(split_string) == 4:\n                \n                    source_latency = strip_seconds(split_string[1])\n                    target_latency = strip_seconds(split_string[2])\n                    handling_latency = strip_seconds(split_string[3])\n\n                    # Makes the date compatible with Excel\n                    date_obj = format_timestamp(timestamp)\n                    excel_datetime = date_obj.strftime("%Y-%m-%d %H:%M:%S")\n                    \n                    # If you're outputting to standard out\n                    #print(f"{in_file_path}\\t{time_stamp}\\t{source_latency}\\t{target_latency}\\t{handling_latency}\\n")\n\n                    return_array.append([in_file_path, timestamp, excel_datetime, source_latency, target_latency, handling_latency])\n                     \n    return return_array\n    \n\nif __name__ == '__main__':\n\n    log_folder = "\/path\/to\/logfile\/dir"\n    out_excel = "OutLatency.xlsx"\n    \n    latency_data = []\n\n    # Loops through files in log_folder\n    for file_name in os.listdir(log_folder):\n\n        focus_file = os.path.join(log_folder, file_name )\n\n        if os.path.isfile(focus_file):\n            filename, file_extension = os.path.splitext(focus_file)\n\n            if file_extension.upper().endswith("LOG"):\n                print(f"Processing file: {focus_file}")\n                return_array = process_file(focus_file)\n\n                latency_data += return_array\n                \n\n    df = pd.DataFrame(latency_data, columns=["File Name", "Time Stamp", "Excel Timestamp", "Source Latency", "Target Latency", "Handling Latency"])\n    df.info()\n\n    # Dump file to Excel; but you can dump to other formats like text etc\n    df.to_excel(out_excel)\n<\/pre><\/div>\n\n\n
And voil\u00e0 – we have an output to Excel to quickly create statistics on latency for a given task(s).<\/p>\n\n\n\n
What statistics to use?<\/h2>\n\n\n\n
Latency is something you can analyse in different ways, depending on what you’re trying to answer. It is also important to pair latency statistics with the change volume that is coming through.<\/p>\n\n\n\n
Has the latency jumped at a specific time because the source database is processing a daily batch? Is there a spike of latency around Christmas time where there are more financial transactions compared to a benign day in February?<\/p>\n\n\n\n
Generally, if the testers are processing the latency data they provide back:<\/p>\n\n\n\n
    \n
  • Average target latency<\/li>\n\n\n\n
  • 90th<\/sup> percentile target latency<\/li>\n\n\n\n
  • 95th<\/sup> percentile target latency<\/li>\n\n\n\n
  • Min target latency<\/li>\n\n\n\n
  • Max target latency<\/li>\n<\/ul>\n\n\n\n
    This is what we use to compare two runs to each other when the source load is consistent and we’re changing a Qlik Replicate task<\/p>\n","protected":false},"excerpt":{"rendered":"
    We have been doing a bit of “Stress and Volume” testing in Qlik Replicate over the past few days; investigating how my latency is introduced to...<\/p>\n","protected":false},"author":1,"featured_media":1659,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"om_disable_all_campaigns":false,"_monsterinsights_skip_tracking":false,"_monsterinsights_sitenote_active":false,"_monsterinsights_sitenote_note":"","_monsterinsights_sitenote_category":0,"footnotes":""},"categories":[18,16],"tags":[69,36],"class_list":["post-1655","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-python","category-qlik-replicate","tag-python","tag-qlikreplicate"],"aioseo_notices":[],"_links":{"self":[{"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/posts\/1655","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcomments&post=1655"}],"version-history":[{"count":2,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/posts\/1655\/revisions"}],"predecessor-version":[{"id":1658,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/posts\/1655\/revisions\/1658"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=\/wp\/v2\/media\/1659"}],"wp:attachment":[{"href":"https:\/\/craftcookcode.com\/index.php?rest_route=%2Fwp%2Fv2%2Fmedia&parent=1655"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=%2Fwp%2Fv2%2Fcategories&post=1655"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/craftcookcode.com\/index.php?rest_route=%2Fwp%2Fv2%2Ftags&post=1655"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}