【 使用环境 】测试环境
【 OB or 其他组件 】obd搭建的3节点集群
【 使用版本 】oceanbase-ce-3.1.4,libobclient-2.0.2
【问题描述】oceanBase observer.log疯狂输出日志,日志等级为info,每个节点observer.log每个小时大概有257M的日志生成,通过tail -f observer.log也发现日志写入速度就像下雨似的非常快,完全看不清日志内容
[root@ob2 log]# ll -h
total 2.4G
-rw-r–r-- 1 admin admin 5.6M Aug 22 09:56 election.log
-rw-r–r-- 1 admin admin 14K Aug 19 11:21 election.log.wf
-rw-r–r-- 1 admin admin 52M Aug 22 09:56 observer.log
-rw-r–r-- 1 admin admin 257M Aug 22 07:02 observer.log.20220822070256
-rw-r–r-- 1 admin admin 257M Aug 22 07:57 observer.log.20220822075705
-rw-r–r-- 1 admin admin 257M Aug 22 08:51 observer.log.20220822085116
-rw-r–r-- 1 admin admin 257M Aug 22 09:45 observer.log.20220822094554
-rw-r–r-- 1 admin admin 3.6M Aug 22 09:56 observer.log.wf
-rw-r–r-- 1 admin admin 19M Aug 22 07:02 observer.log.wf.20220822070256
-rw-r–r-- 1 admin admin 18M Aug 22 07:57 observer.log.wf.20220822075705
-rw-r–r-- 1 admin admin 19M Aug 22 08:51 observer.log.wf.20220822085116
-rw-r–r-- 1 admin admin 19M Aug 22 09:45 observer.log.wf.20220822094554
-rw-r–r-- 1 admin admin 178M Aug 22 09:56 rootservice.log
-rw-r–r-- 1 admin admin 257M Aug 20 11:49 rootservice.log.20220820114932
-rw-r–r-- 1 admin admin 257M Aug 21 00:18 rootservice.log.20220821001848
-rw-r–r-- 1 admin admin 257M Aug 21 12:48 rootservice.log.20220821124854
-rw-r–r-- 1 admin admin 257M Aug 22 01:17 rootservice.log.20220822011726
-rw-r–r-- 1 admin admin 148K Aug 22 09:51 rootservice.log.wf
-rw-r–r-- 1 admin admin 191K Aug 20 11:48 rootservice.log.wf.20220820114932
-rw-r–r-- 1 admin admin 156K Aug 21 00:18 rootservice.log.wf.20220821001848
-rw-r–r-- 1 admin admin 200K Aug 21 12:47 rootservice.log.wf.20220821124854
-rw-r–r-- 1 admin admin 169K Aug 22 01:11 rootservice.log.wf.20220822011726
日志等级查询:
Welcome to the OceanBase. Commands end with ; or \g.
Your OceanBase connection id is 3221706064
Server version: 5.7.25 OceanBase 3.1.4 (r10000092022071511-b4bfa011ceaef428782dcb65ae89190c40b78c2f) (Built Jul 15 2022 11:45:14)
Copyright (c) 2000, 2022, OceanBase and/or its affiliates. All rights reserved.
Type ‘help;’ or ‘\h’ for help. Type ‘\c’ to clear the current input statement.
obclient [(none)]> show parameters like ‘%syslog_level%’;
±------±---------±-------------±---------±-------------±----------±------±-----------------------------------------------------------------------------------------------------------------------±---------±--------±--------±------------------+
| zone | svr_type | svr_ip | svr_port | name | data_type | value | info | section | scope | source | edit_level |
±------±---------±-------------±---------±-------------±----------±------±-----------------------------------------------------------------------------------------------------------------------±---------±--------±--------±------------------+
| zone1 | observer | 192.168.0.48 | 2882 | syslog_level | NULL | INFO | specifies the current level of logging. There are DEBUG, TRACE, INFO, WARN, USER_ERR, ERROR, six different log levels. | OBSERVER | CLUSTER | DEFAULT | DYNAMIC_EFFECTIVE |
| zone1 | observer | 192.168.0.49 | 2882 | syslog_level | NULL | INFO | specifies the current level of logging. There are DEBUG, TRACE, INFO, WARN, USER_ERR, ERROR, six different log levels. | OBSERVER | CLUSTER | DEFAULT | DYNAMIC_EFFECTIVE |
| zone1 | observer | 192.168.0.67 | 2882 | syslog_level | NULL | INFO | specifies the current level of logging. There are DEBUG, TRACE, INFO, WARN, USER_ERR, ERROR, six different log levels. | OBSERVER | CLUSTER | DEFAULT | DYNAMIC_EFFECTIVE |
±------±---------±-------------±---------±-------------±----------±------±-----------------------------------------------------------------------------------------------------------------------±---------±--------±--------±------------------+
3 rows in set (0.053 sec)
obclient [(none)]>
ob部署配置:
Only need to configure when remote login is required
user:
username: admin
password: *****
key_file: your ssh-key file path if need
port: your ssh port, default 22
timeout: ssh connection timeout (second), default 30
oceanbase-ce:
servers:
- name: server1
# Please don’t use hostname, only IP can be supported
ip: 192.168.0.48
- name: server2
ip: 192.168.0.49
- name: server3
ip: 192.168.0.67
global:
# The working directory for OceanBase Database. OceanBase Database is started under this directory. This is a required field.
home_path: /home/admin/oceanbase/ob
# The directory for data storage. The default value is $home_path/store.
# data_dir: /data/data
# The directory for clog, ilog, and slog. The default value is the same as the data_dir value.
# redo_dir: /data/redo
# Please set devname as the network adaptor’s name whose ip is in the setting of severs.
# if set severs as “127.0.0.1”, please set devname as “lo”
# if current ip is 192.168.1.10, and the ip’s network adaptor’s name is “eth0”, please use “eth0”
devname: eth0
# External port for OceanBase Database. The default value is 2881.DO NOT change this value after the cluster is started.
# mysql_port: 2881
# Internal port for OceanBase Database. The default value is 2882. DO NOT change this value after the cluster is started.
# rpc_port: 2882
# Defines the zone for an observer. The default value is zone1.
# zone: zone1
# The maximum running memory for an observer. When ignored, autodeploy calculates this value based on the current server available resource.
# memory_limit: 58G
# The percentage of the maximum available memory to the total memory. This value takes effect only when memory_limit is 0. The default value is 80.
# memory_limit_percentage: 80
# The reserved system memory. system_memory is reserved for general tenants. The default value is 30G. Autodeploy calculates this value based on the current server available resource.
# system_memory: 22G
# The size of a data file. When ignored, autodeploy calculates this value based on the current server available resource.
# datafile_size: 200G
# The percentage of the data_dir space to the total disk space. This value takes effect only when datafile_size is 0. The default value is 90.
# datafile_disk_percentage: 90
# System log level. The default value is INFO.
# syslog_level: INFO
# Print system logs whose levels are higher than WARNING to a separate log file. The default value is true. The default value for autodeploy mode is false.
# enable_syslog_wf: false
# Enable auto system log recycling or not. The default value is false. The default value for autodeploy mode is on.
# enable_syslog_recycle: true
# The maximum number of reserved log files before enabling auto recycling. When set to 0, no logs are deleted. The default value for autodeploy mode is 4.
# max_syslog_file_count: 4
# Cluster name for OceanBase Database. The default value is obcluster. When you deploy OceanBase Database and obproxy, this value must be the same as the cluster_name for obproxy.
# appname: obcluster
# Password for root. The default value is empty.
# root_password:
# Password for proxyro. proxyro_password must be the same as observer_sys_password. The default value is empty.
# proxyro_password:
server1:
zone: zone1
server2:
zone: zone1
server3:
zone: zone1
obproxy-ce:
depends:
- oceanbase-ce
servers:
- 192.168.0.49
global:
# The working directory for obproxy. Obproxy is started under this directory. This is a required field.
home_path: /home/admin/oceanbase/obproxy
skip_proxy_sys_private_check: true
enable_strict_kernel_release: false
# External port. The default value is 2883.
# listen_port: 2883
# The Prometheus port. The default value is 2884.
# prometheus_listen_port: 2884
# rs_list is the root server list for observers. The default root server is the first server in the zone.
# The format for rs_list is observer_ip:observer_mysql_port;observer_ip:observer_mysql_port.
# Ignore this value in autodeploy mode.
# rs_list: 127.0.0.1:2881
# Cluster name for the proxy OceanBase Database. The default value is obcluster. This value must be set to the same with the appname for OceanBase Database.
# cluster_name: obcluster
# Password for obproxy system tenant. The default value is empty.
# obproxy_sys_password:
# Password for proxyro. proxyro_password must be the same with proxyro_password. The default value is empty.
# observer_sys_password:
日志内容(由于字数限制,只贴了少部分日志):
[root@ob2 log]# tail -f observer.log
[2022-08-22 10:04:30.384803] INFO [RPC.FRAME] ob_net_easy.cpp:348 [23553][0][Y0-0000000000000000] [lt=24] [dc=0] [RPC EASY STAT](conn count=7, request done=6474120, request doing=0)
[2022-08-22 10:04:30.395598] INFO [RPC.FRAME] ob_net_easy.cpp:405 [23561][0][Y0-0000000000000000] [lt=18] [dc=0] [BATCH_RPC EASY STAT](conn count=0, request done=90, request doing=0)
[2022-08-22 10:04:30.395629] INFO [RPC.FRAME] ob_net_easy.cpp:348 [23558][0][Y0-0000000000000000] [lt=36] [dc=0] [RPC EASY STAT](conn count=1, request done=1640803, request doing=0)
[2022-08-22 10:04:30.401399] INFO [RPC.FRAME] ob_net_easy.cpp:405 [23565][0][Y0-0000000000000000] [lt=31] [dc=0] [BATCH_RPC EASY STAT](conn count=0, request done=78, request doing=0)
[2022-08-22 10:04:30.402142] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=61] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.410032] INFO [RPC.FRAME] ob_net_easy.cpp:405 [23572][0][Y0-0000000000000000] [lt=70] [dc=0] [BATCH_RPC EASY STAT](conn count=0, request done=91, request doing=0)
[2022-08-22 10:04:30.418192] INFO [COMMON] ob_kvcache_store.cpp:799 [23203][100][Y0-0000000000000000] [lt=10] [dc=0] Wash compute wash size(sys_total_wash_size=826277888, global_cache_size=67096256, tenant_max_wash_size=67096256, tenant_min_wash_size=0, tenant_ids_=[1, 500])
[2022-08-22 10:04:30.418223] INFO [COMMON] ob_kvcache_store.cpp:323 [23203][100][Y0-0000000000000000] [lt=17] [dc=0] Wash time detail, (refresh_score_time=38, compute_wash_size_time=167, wash_sort_time=6, wash_time=2)
[2022-08-22 10:04:30.418676] INFO [STORAGE.TRANS] ob_tenant_weak_read_service.cpp:496 [23538][762][Y0-0000000000000000] [lt=21] [dc=0] [WRS] [TENANT_WEAK_READ_SERVICE] [STAT](tenant_id=1, server_version={version:1661133870304068, total_part_count:1207, valid_inner_part_count:1200, valid_user_part_count:7}, server_version_delta=114581, in_cluster_service=true, cluster_version=1661133870102964, min_cluster_version=1661133870102964, max_cluster_version=1661133870102964, get_cluster_version_err=0, cluster_version_delta=315685, cluster_service_master=“192.168.0.48:2882”, cluster_service_pkey={tid:1099511628002, partition_id:0, part_cnt:0}, post_cluster_heartbeat_count=4227103, succ_cluster_heartbeat_count=536, cluster_heartbeat_interval=50000, local_cluster_version=0, local_cluster_delta=1661133870418649, force_self_check=false, weak_read_refresh_interval=50000)
[2022-08-22 10:04:30.419831] INFO [STORAGE.TRANS] ob_trans_part_ctx.cpp:731 [23538][762][YB42C0A80030-0005E68F9C9DF54E] [lt=25] [dc=0] update gts cache success(updated=false, context={ObDistTransCtx:{ObTransCtx:{this:0x7f4f2d440a10, ctx_type:2, trans_id:{hash:3748690338703195436, inc:8568219, addr:“192.168.0.48:2882”, t:1661133870419617}, tenant_id:1, is_exiting:false, trans_type:0, is_readonly:false, trans_expired_time:1661133900419471, self:{tid:1099511628002, partition_id:0, part_cnt:0}, state:{prepare_version:-1, state:0}, cluster_version:12884967428, trans_need_wait_wrap:{receive_gts_ts:{mts:0}, need_wait_interval_us:0}, trans_param:[access_mode=1, type=2, isolation=1, magic=17361641481138401520, autocommit=1, consistency_type=0(CURRENT_READ), read_snapshot_type=2(PARTICIPANT_SNAPSHOT), cluster_version=12884967428, is_inner_trans=1], can_elr:false, uref:1073741825, ctx_create_time:1661133870419388}, scheduler:“192.168.0.48:2882”, coordinator:{tid:18446744073709551615, partition_id:-1, part_idx:268435455, subpart_idx:268435455}, participants:[{tid:1099511628002, partition_id:0, part_cnt:0}], request_id:-1, timeout_task:{is_inited:true, is_registered:true, is_running:false, delay:30195183, ctx:0x7f4f2d440a10, bucket_idx:6680, run_ticket:332226780123, is_scheduled:true, prev:0x7f502f01a340, next:0x7f502f01a340}, xid:{gtrid_str:"", bqual_str:"", format_id:1, gtrid_str_.ptr():“data_size:0, data:”, bqual_str_.ptr():“data_size:0, data:”}}, snapshot_version:1661133870359716, local_trans_version:-1, submit_log_pending_count:0, submit_log_count:0, stmt_info:{sql_no:0, start_task_cnt:0, end_task_cnt:0, need_rollback:false, task_info:{tasks_:[]}}, global_trans_version:-1, redo_log_no:0, mutator_log_no:0, session_id:1, is_gts_waiting:false, part_trans_action:-1, timeout_task:{is_inited:true, is_registered:true, is_running:false, delay:30195183, ctx:0x7f4f2d440a10, bucket_idx:6680, run_ticket:332226780123, is_scheduled:true, prev:0x7f502f01a340, next:0x7f502f01a340}, batch_commit_trans:false, batch_commit_state:0, is_dup_table_trans:false, last_ask_scheduler_status_ts:1661133870419719, last_ask_scheduler_status_response_ts:1661133870419720, ctx_dependency_wrap:{prev_trans_arr:[], next_trans_arr:[], prev_trans_commit_count:0}, preassigned_log_meta:{log_id_:18446744073709551615, submit_timestamp_:-1, proposal_id_:{time_to_usec:-1, server:“0.0.0.0”}}, is_dup_table_prepare:false, dup_table_syncing_log_id:18446744073709551615, is_prepare_leader_revoke:false, is_local_trans:true, forbidden_sql_no:-1, is_dirty_:false, undo_status:{undo_action_arr:[]}, max_durable_sql_no:0, max_durable_log_ts:0, mt_ctx_.get_checksum_log_ts():0, is_changing_leader:false, has_trans_state_log:false, is_trans_state_sync_finished:false, status:0, same_leader_batch_partitions_count:0, is_hazardous_ctx:false, mt_ctx_.get_callback_count():0, in_xa_prepare_state:false, is_listener:false, last_replayed_redo_log_id:0, status:0, is_xa_trans_prepared:true, redo_log_id_serialize_size:1, participants_serialize_size:1, undo_serialize_size:7})
[2022-08-22 10:04:30.422313] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=55] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.423912] INFO [SERVER] ob_inner_sql_connection.cpp:1300 [23538][762][Y0-0000000000000000] [lt=27] [dc=0] execute write sql(ret=0, tenant_id=1, affected_rows=1, sql=" update all_weak_read_service set min_version=1661133870270977, max_version=1661133870270977 where level_id = 0 and level_value = ‘’ and min_version = 1661133870102964 and max_version = 1661133870102964 ")
[2022-08-22 10:04:30.424576] INFO [RPC.FRAME] ob_net_easy.cpp:405 [23570][0][Y0-0000000000000000] [lt=30] [dc=0] [BATCH_RPC EASY STAT](conn count=0, request done=71, request doing=0)
[2022-08-22 10:04:30.424634] INFO [RPC.FRAME] ob_net_easy.cpp:405 [23575][0][Y0-0000000000000000] [lt=34] [dc=0] [BATCH_RPC EASY STAT](conn count=0, request done=85, request doing=0)
[2022-08-22 10:04:30.425018] INFO [RPC.FRAME] ob_net_easy.cpp:405 [23576][0][Y0-0000000000000000] [lt=35] [dc=0] [BATCH_RPC EASY STAT](conn count=0, request done=86, request doing=0)
[2022-08-22 10:04:30.425621] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23581][0][Y0-0000000000000000] [lt=45] [dc=0] [MYSQL EASY STAT](conn count=2, request done=39, request doing=0)
[2022-08-22 10:04:30.429248] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23580][0][Y0-0000000000000000] [lt=22] [dc=0] [MYSQL EASY STAT](conn count=0, request done=49, request doing=0)
[2022-08-22 10:04:30.430497] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23582][0][Y0-0000000000000000] [lt=29] [dc=0] [MYSQL EASY STAT](conn count=0, request done=32, request doing=0)
[2022-08-22 10:04:30.430893] INFO [SERVER] ob_backup_operator.cpp:3306 [23268][228][Y0-0000000000000000] [lt=45] [dc=0] get backup info string value(sql=select value from all_backup_info where name = ‘inner_table_version’, name=“inner_table_version”, real_length=1, buf=“3”)
[2022-08-22 10:04:30.436854] INFO [SHARE] ob_log_archive_backup_info_mgr.cpp:924 [23268][228][Y0-0000000000000000] [lt=42] [dc=0] get status(tmp_status=1, value_str=“STOP”)
[2022-08-22 10:04:30.436919] INFO [SHARE] ob_log_archive_backup_info_mgr.cpp:634 [23268][228][Y0-0000000000000000] [lt=38] [dc=0] succeed to get backup log archive backup status(sql=select backup_dest, tenant_id, incarnation, log_archive_round, time_to_usec(min_first_time) min_first_time, time_to_usec(max_next_time) max_next_time, status , is_mount_file_created, compatible, backup_piece_id, start_piece_id from all_backup_log_archive_status_v2 where tenant_id=1 , info={status:{tenant_id:1, copy_id:0, start_ts:0, checkpoint_ts:0, status:1, incarnation:1, round:0, status_str:“STOP”, is_mark_deleted:false, is_mount_file_created:false, compatible:0, backup_piece_id:0, start_piece_id:0}, backup_dest:""})
[2022-08-22 10:04:30.438021] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23584][0][Y0-0000000000000000] [lt=38] [dc=0] [MYSQL EASY STAT](conn count=0, request done=93, request doing=0)
[2022-08-22 10:04:30.438408] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23578][0][Y0-0000000000000000] [lt=22] [dc=0] [MYSQL EASY STAT](conn count=0, request done=19, request doing=0)
[2022-08-22 10:04:30.438625] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23585][0][Y0-0000000000000000] [lt=46] [dc=0] [MYSQL EASY STAT](conn count=2, request done=11513, request doing=0)
[2022-08-22 10:04:30.442514] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=57] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.460739] INFO [STORAGE.TRANS] ob_tenant_weak_read_server_version_mgr.cpp:130 [23792][1191][Y0-0000000000000000] [lt=43] [dc=0] [WRS] update tenant weak read server version(tenant_id=1, server_version={version:1661133870304068, total_part_count:1207, valid_inner_part_count:1200, valid_user_part_count:7, epoch_tstamp:1661133870429640}, version_delta=156654)
[2022-08-22 10:04:30.462716] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=36] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.470837] INFO [CLOG] ob_log_archive_and_restore_driver.cpp:232 [23781][1169][YB42C0A80030-0005E68F944C248A] [lt=48] [dc=0] ObLogArchiveAndRestoreDriver round_cost_time(round_cost_time=2239, sleep_ts=497761, cycle_num=508631)
[2022-08-22 10:04:30.482903] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=34] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.501459] INFO [RPC.FRAME] ob_net_easy.cpp:434 [23591][0][Y0-0000000000000000] [lt=24] [dc=0] [MYSQL EASY STAT](conn count=0, request done=0, request doing=0)
[2022-08-22 10:04:30.503120] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=32] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.523350] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=33] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.540697] INFO [STORAGE.TRANS] ob_trans_part_ctx.cpp:731 [23538][762][YB42C0A80030-0005E68F9C9DF54F] [lt=28] [dc=0] update gts cache success(updated=false, context={ObDistTransCtx:{ObTransCtx:{this:0x7f4f2d440a10, ctx_type:2, trans_id:{hash:3739143355455414144, inc:8568229, addr:“192.168.0.48:2882”, t:1661133870540312}, tenant_id:1, is_exiting:false, trans_type:0, is_readonly:false, trans_expired_time:1661133900540020, self:{tid:1099511628002, partition_id:0, part_cnt:0}, state:{prepare_version:-1, state:0}, cluster_version:12884967428, trans_need_wait_wrap:{receive_gts_ts:{mts:0}, need_wait_interval_us:0}, trans_param:[access_mode=1, type=2, isolation=1, magic=17361641481138401520, autocommit=1, consistency_type=0(CURRENT_READ), read_snapshot_type=2(PARTICIPANT_SNAPSHOT), cluster_version=12884967428, is_inner_trans=1], can_elr:false, uref:1073741825, ctx_create_time:1661133870539627}, scheduler:“192.168.0.48:2882”, coordinator:{tid:18446744073709551615, partition_id:-1, part_idx:268435455, subpart_idx:268435455}, participants:[{tid:1099511628002, partition_id:0, part_cnt:0}], request_id:-1, timeout_task:{is_inited:true, is_registered:true, is_running:false, delay:30413655, ctx:0x7f4f2d440a10, bucket_idx:6748, run_ticket:332226780191, is_scheduled:true, prev:0x7f502f01d640, next:0x7f502f01d640}, xid:{gtrid_str:"", bqual_str:"", format_id:1, gtrid_str.ptr():“data_size:0, data:”, bqual_str.ptr():“data_size:0, data:”}}, snapshot_version:1661133870419488, local_trans_version:-1, submit_log_pending_count:0, submit_log_count:0, stmt_info:{sql_no:0, start_task_cnt:0, end_task_cnt:0, need_rollback:false, task_info:{tasks:[]}}, global_trans_version:-1, redo_log_no:0, mutator_log_no:0, session_id:1, is_gts_waiting:false, part_trans_action:-1, timeout_task:{is_inited:true, is_registered:true, is_running:false, delay:30413655, ctx:0x7f4f2d440a10, bucket_idx:6748, run_ticket:332226780191, is_scheduled:true, prev:0x7f502f01d640, next:0x7f502f01d640}, batch_commit_trans:false, batch_commit_state:0, is_dup_table_trans:false, last_ask_scheduler_status_ts:1661133870540501, last_ask_scheduler_status_response_ts:1661133870540502, ctx_dependency_wrap:{prev_trans_arr:[], next_trans_arr:[], prev_trans_commit_count:0}, preassigned_log_meta:{log_id:18446744073709551615, submit_timestamp:-1, proposal_id:{time_to_usec:-1, server:“0.0.0.0”}}, is_dup_table_prepare:false, dup_table_syncing_log_id:18446744073709551615, is_prepare_leader_revoke:false, is_local_trans:true, forbidden_sql_no:-1, is_dirty_:false, undo_status:{undo_action_arr:[]}, max_durable_sql_no:0, max_durable_log_ts:0, mt_ctx_.get_checksum_log_ts():0, is_changing_leader:false, has_trans_state_log:false, is_trans_state_sync_finished:false, status:0, same_leader_batch_partitions_count:0, is_hazardous_ctx:false, mt_ctx_.get_callback_count():0, in_xa_prepare_state:false, is_listener:false, last_replayed_redo_log_id:0, status:0, is_xa_trans_prepared:true, redo_log_id_serialize_size:1, participants_serialize_size:1, undo_serialize_size:7})
[2022-08-22 10:04:30.543662] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=39] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.563869] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=38] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.584103] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=39] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.604350] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=37] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.609201] INFO [COMMON] ob_kvcache_store.cpp:799 [23203][100][Y0-0000000000000000] [lt=19] [dc=0] Wash compute wash size(sys_total_wash_size=826277888, global_cache_size=67096256, tenant_max_wash_size=67096256, tenant_min_wash_size=0, tenant_ids_=[1, 500])
[2022-08-22 10:04:30.609242] INFO [COMMON] ob_kvcache_store.cpp:323 [23203][100][Y0-0000000000000000] [lt=25] [dc=0] Wash time detail, (refresh_score_time=35, compute_wash_size_time=161, wash_sort_time=6, wash_time=1)
[2022-08-22 10:04:30.624639] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=41] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.644864] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=43] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.645272] WARN [CLOG] finish_timer (ob_log_timer_utility.h:42) [23359][0][Y0-0000000000000000] [lt=14] [dc=0] cost too much time(file="/home/jenkins/agent/workspace/rpm-oceanbase-ce-3.1.4-1.1.5/ob_source_code_dir/src/clog/ob_clog_file_writer.cpp", line=688, time=103002)
[2022-08-22 10:04:30.645370] WARN [CLOG] process_log_items (ob_clog_writer.cpp:272) [23359][0][Y0-0000000000000000] [lt=35] [dc=0] slow flush(flush_time=46, io_time=103061, file_id=38, flush_start_offset=10755728, file_offset=10756311)
[2022-08-22 10:04:30.646834] INFO [SERVER] ob_inner_sql_connection.cpp:1300 [23538][762][Y0-0000000000000000] [lt=53] [dc=0] execute write sql(ret=0, tenant_id=1, affected_rows=1, sql=" update all_weak_read_service set min_version=1661133870303303, max_version=1661133870303303 where level_id = 0 and level_value = ‘’ and min_version = 1661133870270977 and max_version = 1661133870270977 “)
[2022-08-22 10:04:30.647068] WARN [LIB] ~ObTimeGuard (utility.h:761) [23538][762][Y0-0000000000000000] [lt=45] [dc=0] destruct(*this=time guard ‘[WRS] [TENANT_WEAK_READ_SERVICE] tenant_id=1, thread_timer_task’ cost too much time, used=108719, time_dist: do_cluster_heartbeat=24, generate_cluster_version=108688)
[2022-08-22 10:04:30.665100] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=41] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.685332] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=40] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.692877] INFO [STORAGE] ob_trans_checkpoint_worker.cpp:104 [23787][1181][Y0-0000000000000000] [lt=73] [dc=0] transaction checkpoint worker statistics(avg_time=2, valid_user_part_count=0, valid_inner_part_count=0)
[2022-08-22 10:04:30.700333] INFO [STORAGE.TRANS] ob_trans_part_ctx.cpp:731 [23538][762][YB42C0A80030-0005E68F9C9DF550] [lt=36] [dc=0] update gts cache success(updated=false, context={ObDistTransCtx:{ObTransCtx:{this:0x7f4f2d440a10, ctx_type:2, trans_id:{hash:12524533783331706332, inc:8568230, addr:“192.168.0.48:2882”, t:1661133870699997}, tenant_id:1, is_exiting:false, trans_type:0, is_readonly:false, trans_expired_time:1661133900699718, self:{tid:1099511628002, partition_id:0, part_cnt:0}, state:{prepare_version:-1, state:0}, cluster_version:12884967428, trans_need_wait_wrap:{receive_gts_ts:{mts:0}, need_wait_interval_us:0}, trans_param:[access_mode=1, type=2, isolation=1, magic=17361641481138401520, autocommit=1, consistency_type=0(CURRENT_READ), read_snapshot_type=2(PARTICIPANT_SNAPSHOT), cluster_version=12884967428, is_inner_trans=1], can_elr:false, uref:1073741825, ctx_create_time:1661133870699090}, scheduler:“192.168.0.48:2882”, coordinator:{tid:18446744073709551615, partition_id:-1, part_idx:268435455, subpart_idx:268435455}, participants:[{tid:1099511628002, partition_id:0, part_cnt:0}], request_id:-1, timeout_task:{is_inited:true, is_registered:true, is_running:false, delay:30705903, ctx:0x7f4f2d440a10, bucket_idx:6839, run_ticket:332226780282, is_scheduled:true, prev:0x7f502f021a80, next:0x7f502f021a80}, xid:{gtrid_str:”", bqual_str:"", format_id:1, gtrid_str.ptr():“data_size:0, data:”, bqual_str.ptr():“data_size:0, data:”}}, snapshot_version:1661133870540742, local_trans_version:-1, submit_log_pending_count:0, submit_log_count:0, stmt_info:{sql_no:0, start_task_cnt:0, end_task_cnt:0, need_rollback:false, task_info:{tasks_:[]}}, global_trans_version:-1, redo_log_no:0, mutator_log_no:0, session_id:1, is_gts_waiting:false, part_trans_action:-1, timeout_task:{is_inited:true, is_registered:true, is_running:false, delay:30705903, ctx:0x7f4f2d440a10, bucket_idx:6839, run_ticket:332226780282, is_scheduled:true, prev:0x7f502f021a80, next:0x7f502f021a80}, batch_commit_trans:false, batch_commit_state:0, is_dup_table_trans:false, last_ask_scheduler_status_ts:1661133870700138, last_ask_scheduler_status_response_ts:1661133870700139, ctx_dependency_wrap:{prev_trans_arr:[], next_trans_arr:[], prev_trans_commit_count:0}, preassigned_log_meta:{log_id_:18446744073709551615, submit_timestamp_:-1, proposal_id_:{time_to_usec:-1, server:“0.0.0.0”}}, is_dup_table_prepare:false, dup_table_syncing_log_id:18446744073709551615, is_prepare_leader_revoke:false, is_local_trans:true, forbidden_sql_no:-1, is_dirty_:false, undo_status:{undo_action_arr:[]}, max_durable_sql_no:0, max_durable_log_ts:0, mt_ctx_.get_checksum_log_ts():0, is_changing_leader:false, has_trans_state_log:false, is_trans_state_sync_finished:false, status:0, same_leader_batch_partitions_count:0, is_hazardous_ctx:false, mt_ctx_.get_callback_count():0, in_xa_prepare_state:false, is_listener:false, last_replayed_redo_log_id:0, status:0, is_xa_trans_prepared:true, redo_log_id_serialize_size:1, participants_serialize_size:1, undo_serialize_size:7})
[2022-08-22 10:04:30.705683] INFO [STORAGE] ob_pg_sstable_garbage_collector.cpp:188 [23285][262][Y0-0000000000000000] [lt=39] [dc=0] do one gc free sstable by queue(ret=0, free sstable cnt=0)
[2022-08-22 10:04:30.708564] INFO [STORAGE] ob_tenant_config_mgr.cpp:96 [23551][788][Y0-0000000000000000] [lt=20] [dc=0] tenant units not changed, no need to write(tenant_units=[{tenant_id:1, has_memstore:true, unit_stat:0, config:{unit_config_id:1, name:“sys_unit_config”, max_cpu:“1.500000000000000000e+01”, min_cpu:“1.000000000000000000e+00”, max_memory:5368709120, min_memory:1073741824, max_disk_size:107374182400, max_iops:3000, min_iops:128, max_session_num:200}, mode:0, create_timestamp:1660785869359810, is_removed:false}])
[2022-08-22 10:04:30.708649] INFO ob_tenant_mutil_allocator.cpp:295 [23551][788][Y0-0000000000000000] [lt=47] [dc=0] finish set nway(tenant_id_=1, nway=15)
[2022-08-22 10:04:30.708694] INFO ob_tenant_mutil_allocator_mgr.cpp:322 [23551][788][Y0-0000000000000000] [lt=18] [dc=0] ObTenantMutilAllocator update tenant mem_limit finished(ret=0, tenant_id=1, nway=15, new_tma_limit=2684354550, pre_tma_limit=2684354550, cur_memstore_limit_percent=50, tenant_config={tenant_id:1, has_memstore:true, unit_stat:0, config:{unit_config_id:1, name:“sys_unit_config”, max_cpu:“1.500000000000000000e+01”, min_cpu:“1.000000000000000000e+00”, max_memory:5368709120, min_memory:1073741824, max_disk_size:107374182400, max_iops:3000, min_iops:128, max_session_num:200}, mode:0, create_timestamp:1660785869359810, is_removed:false})
[2022-08-22 10:04:30.708721] INFO ob_tenant_mutil_allocator_mgr.cpp:334 [23551][788][Y0-0000000000000000] [lt=19] [dc=0] succ to set_memstore_threshold of memstore allocator(tenant_id=1, ret=0)