[IMPALA-10702] Add warning logs for slow or large catalogd response

• Type: Improvement
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Fix Version/s: Impala 4.1.0
• Component/s: Catalog
• Epic Color: ghx-label-10
• Assignee: Quanlong Huang
• Reporter: Quanlong Huang
• Created: 12/May/21 07:48
• Updated: 24/May/21 09:17
• Resolved: 21/May/21 02:09

Description

It'd be helpful to log the slow or large responses of catalogd in debugging scalability issues like IMPALA-7501, IMPALA-9896.

For instances:

W0512 15:30:44.378841 23179 JniUtil.java:162] Response too slow: size=21195 (20.70KB), duration=266454ms (4m26s), method: getPartialCatalogObject, request: TGetPartialCatalogObjectRequest(protocol_version:V1, object_desc:TCatalogObject(type:TABLE, catalog_version:0, table:TTable(db_name:db1, tbl_name:tbl1)), table_info_selector:TTableInfoSelector(want_hms_table:true, want_partition_names:false, want_partition_metadata:false, want_partition_files:false, want_partition_stats:false, want_table_constraints:true, table_id:-1))

W0512 15:30:58.849990 23179 JniUtil.java:162] Response too large: size=1823012484 (1.70GB), duration=12202ms (12s202ms), method: getPartialCatalogObject, request: TGetPartialCatalogObjectRequest(protocol_version:V1, object_desc:TCatalogObject(type:TABLE, catalog_version:1615, table:TTable(db_name:db1, tbl_name:tbl1)), table_info_selector:TTableInfoSelector(want_hms_table:false, partition_ids:[0, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19, 20, 21, 22, 23, 24, 25, 26, 27, 28, 29, 30, 31, 32, 33, 34, 35, 36, 37, 38, 39, 40, 41, 42, 43, 44, 45, 46, 47, 48, 49, 50, 51, 52, 53, 54, 55, 56, 57, 58, 59, 60, 61, 62, 63, 64, 65, 66, 67, 68, 69, 70, 71, 72, 73, 74, 75, 76, 77, 78, 79, 80, 81, 82, 83, 84, 85, 86, 87, 88, 89, 90, 91, 92, 93, 94, 95, 96, 97, 98, 99, 100, 101, 102, 103, 104, 105, 106, 107, 108, 109, 110, 111, 112, 113, 114, 115, 116, 117, 118, 119, 120, 121, 122, 123, 124, 125, 126, 127, 128, 129, 130, 131, 132, 133, 134, 135, 136, 137, 138, 139, 140, 141, 142, 143, 144, 145, 146, 147, 148, 149, 150, 151, 152, 153, 154, 155, 156, 157, 158, 159, 160, 161, 162, 163, 164, 165, 166, 167, 168, 1... 

Or responses that are both slow and large:

W0512 15:39:25.564447 25217 JniUtil.java:162] Response too large and too slow: size=71390662 (68.08MB), duration=248180ms (4m8s), method: resetMetadata, request: TResetMetadataRequest(protocol_version:V1, header:TCatalogServiceRequestHeader(requesting_user:quanlong, want_minimal_response:false), is_refresh:true, table_name:TTableName(db_name:db1, table_name:tbl1), sync_ddl:false, refresh_updated_hms_partitions:false, debug_action:)

Issue Links

• relates to: IMPALA-7501 Slim down metastore Partition objects in LocalCatalog cache
• relates to: IMPALA-9896 OutOfMemoryError: Requested array size exceeds VM limit when LocalCatalog is enabled