Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Milvus server hung.. #2574

Closed
chenrulongmaster opened this issue Jun 16, 2020 · 7 comments
Closed

Milvus server hung.. #2574

chenrulongmaster opened this issue Jun 16, 2020 · 7 comments
Assignees
@yhmo
Labels
kind/support Issues that users need help

Comments

@chenrulongmaster
Copy link

Describe the bug
Milvus server hung. After running over 4 weeks, today the server hung suddenly.

Steps/Code to reproduce behavior
May not be able to reproduce.

Environment details

  • Centos7， GTX 2080Ti 10G * 2
  • Docker milvusdb/milvus:0.7.0-gpu-d031120-40c7e8
  • Milvus version v0.7.0
  • config file
    server_config.txt

Additional context
There is not error logs nor fatal logs. I can find something in DB and debug logs.
In mysql， there are two records:
image

In debug logs, its printing as below:
image

After restarted docker server, it recovered. and that two records in Mysql disappeared.

And I found some debug logs... Seems there are some thing not released. Pls search by 1592185901761660000 to check the logs

2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Mark ongoing file:1592085188124571000 refcount:1
2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Mark ongoing file:1592093770722822000 refcount:1
2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Mark ongoing file:1592107451249160000 refcount:1
2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Mark ongoing file:1592168334150603000 refcount:1
2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Mark ongoing file:1592177581891370000 refcount:1
2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Mark ongoing file:1592185901761660000 refcount:1
2020-06-15 09:52:04,798 | DEBUG | default | [ENGINE] Engine query begin, index file count: 8
2020-06-15 09:52:04,798 | DEBUG | default | [SERVER] SearchJob 5508290 add index file: 921037
2020-06-15 09:52:04,798 | DEBUG | default | [SERVER] SearchJob 5508290 add index file: 925706
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 1
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 1
2020-06-15 09:52:04,800 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000004 second [0.004292 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001267 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000710 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000959 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000003 second [0.003095 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000689 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000463 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000002 second [0.001506 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001089 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000682 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001483 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000219 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000538 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000527 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000525 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001284 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000680 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000865 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000214 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000888 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000731 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000747 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000240 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000386 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000675 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000548 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000682 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000027 second [0.026714 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000693 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000317 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000709 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000362 second [0.361822 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000638 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000329 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000700 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] MySQLMetaImpl::Size: SELECT IFNULL(SUM(file_size),0) AS sum FROM TableFiles WHERE file_type <> 4;
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.001784 second [1.783912 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] get uids 286781 from index /var/lib/milvus/db/tables/1592060088341038000/1592185901761660000/1592185901761660000
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000053 second [0.052595 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] DoSearch file id:931852: job 5508290 nq 10 topk 5, do search (0.002205 second [2.204683 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] DoSearch file id:931852: job 5508290 nq 10 topk 5, reduce topk (0.000021 second [0.020543 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 931852
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] DoSearch file id:931852: totally cost (0.002248 second [2.248245 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] MemTable flush
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] Flushing table: 1592060088341038000
2020-06-15 09:52:04,804 | DEBUG | default | [ENGINE] Initializing bloom filter took 0.000208521 s
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] DoSearch file id:928300: job 5508290 nq 10 topk 5, reduce topk (0.000007 second [0.006580 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 928300
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] DoSearch file id:928300: totally cost (0.004451 second [4.451273 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000632 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,805 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000007 second [0.006701 ms])
2020-06-15 09:52:04,806 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000715 ms])
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Adding 50 ids to bloom filter took 0.00350843 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing bloom filter took 7.628e-06 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing bloom filter took 0.00381756 s in total
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing raw vectors took 9.7693e-05 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing uids took 1.8096e-05 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing vectors and uids took 0.000255234 s in total
2020-06-15 09:52:04,808 | DEBUG | default | [ENGINE] Writing deleted docs took 0.000101255 s
2020-06-15 09:52:04,808 | DEBUG | default | [ENGINE] MySQLMetaImpl::UpdateTableFile: SELECT state FROM Tables WHERE table_id = '1592060088341038000';
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] Update single table file, file id = 1592185924569713000
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] New raw file 1592185924569713000 of size 60000 bytes, lsn = 0
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] Flushed segment 1592185924569713000
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] MySQLMetaImpl::UpdateTableFlushLSN: UPDATE Tables SET flush_lsn = 0 WHERE table_id = '1592060088341038000';
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.004850 second [4.850397 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] get uids 445000 from index /var/lib/milvus/db/tables/1591977144528510000/1592093767724537000/1592093770722822000
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000025 second [0.025218 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] DoSearch file id:906800: job 5508290 nq 10 topk 5, do search (0.004896 second [4.895675 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] DoSearch file id:906800: job 5508290 nq 10 topk 5, reduce topk (0.000007 second [0.006757 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 906800
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] DoSearch file id:906800: totally cost (0.004913 second [4.912831 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000422 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000007 second [0.006822 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000665 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Successfully update table flush_lsn, table id = 1592060088341038000
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Finished flushing for table 1592060088341038000 in 0.00708644 s
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Flushed table: 1592060088341038000
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] End flush all tables
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] Mark ongoing file:1592185901761660000 refcount:2
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] Mark ongoing file:1592185924569713000 refcount:1
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] Merge files for table: 1592060088341038000
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.008838 second [8.837506 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] get uids 444761 from index /var/lib/milvus/db/tables/1591977144528510000/1592085184848009000/1592085188124571000
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000033 second [0.033409 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] DoSearch file id:904659: job 5508290 nq 10 topk 5, do search (0.008910 second [8.909594 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] DoSearch file id:904659: job 5508290 nq 10 topk 5, reduce topk (0.000013 second [0.012605 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 904659
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] DoSearch file id:904659: totally cost (0.008948 second [8.947505 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000555 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000013 second [0.012585 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000683 ms])
2020-06-15 09:52:04,813 | DEBUG | default | [ENGINE] Successfully create table file, file id = 1592185924812270000
2020-06-15 09:52:04,813 | DEBUG | default | [ENGINE] Merging from /var/lib/milvus/db/tables/1592060088341038000/1592185901761660000 to /var/lib/milvus/db/tables/1592060088341038000/1592185924812270000
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.007463 second [7.462992 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [ENGINE] get uids 444539 from index /var/lib/milvus/db/tables/1591977144528510000/1592126799378535000/1592126802677400000
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000030 second [0.029569 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] DoSearch file id:918347: job 5508290 nq 10 topk 5, do search (0.007513 second [7.512870 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] DoSearch file id:918347: job 5508290 nq 10 topk 5, reduce topk (0.000006 second [0.006290 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 918347
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] DoSearch file id:918347: totally cost (0.007530 second [7.529642 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000340 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,798 | DEBUG | default | [SERVER] SearchJob 5508290 add index file: 931852
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 1
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 1
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,799 | DEBUG | default | [ENGINE] EngineFactory index type: 3
2020-06-15 09:52:04,800 | DEBUG | default | [ENGINE] Index params: {"dim":300,"gpu_id":0,"metric_type":"IP","nlist":16384}
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu0 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] FaissIVFSQ8Pass: nq > gpu_search_threshold, specify gpu1 to search!
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000004 second [0.004292 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001267 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001013 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000886 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000710 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000959 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000003 second [0.003095 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000689 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] Search task load file id:931852 DISK2CPU file type:1 size:0 bytes from location: /var/lib/milvus/db/tables/1592060088341038000/1592185901761660000/1592185901761660000 totally cost (0.000019 second [0.018913 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000502 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000002 second [0.001729 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000794 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] Search task load file id:928300 DISK2CPU file type:3 size:145764019 bytes from location: /var/lib/milvus/db/tables/1592060088341038000/1592177578927133000/1592177581891370000 totally cost (0.000012 second [0.012206 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000463 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001428 ms])
2020-06-15 09:52:04,800 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.001097 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000002 second [0.001506 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:904659 DISK2CPU file type:3 size:145790483 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592085184848009000/1592085188124571000 totally cost (0.000010 second [0.009870 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:931852 CPU2GPU:0 file type:1 size:0 bytes from location: /var/lib/milvus/db/tables/1592060088341038000/1592185901761660000/1592185901761660000 totally cost (0.000018 second [0.017899 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001089 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:906800 DISK2CPU file type:3 size:145868927 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592093767724537000/1592093770722822000 totally cost (0.000010 second [0.009680 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001483 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:904659 CPU2GPU:0 file type:3 size:145790483 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592085184848009000/1592085188124571000 totally cost (0.000012 second [0.012252 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:928300 CPU2GPU:1 file type:3 size:145764019 bytes from location: /var/lib/milvus/db/tables/1592060088341038000/1592177578927133000/1592177581891370000 totally cost (0.000019 second [0.019188 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000219 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000538 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000527 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:906800 CPU2GPU:1 file type:3 size:145868927 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592093767724537000/1592093770722822000 totally cost (0.000011 second [0.010619 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000525 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.001284 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000680 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:912444 DISK2CPU file type:3 size:145753547 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592107448158549000/1592107451249160000 totally cost (0.000010 second [0.009549 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000865 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000214 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:918347 DISK2CPU file type:3 size:145718483 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592126799378535000/1592126802677400000 totally cost (0.000009 second [0.009010 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000888 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000731 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000747 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000240 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000386 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000675 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:921037 DISK2CPU file type:1 size:0 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592142841055850000/1592142841055850000 totally cost (0.000010 second [0.009528 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000548 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000682 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000027 second [0.026714 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:912444 CPU2GPU:0 file type:3 size:145753547 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592107448158549000/1592107451249160000 totally cost (0.000011 second [0.010898 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:925706 DISK2CPU file type:3 size:145802471 bytes from location: /var/lib/milvus/db/tables/1592060088341038000/1592168331065017000/1592168334150603000 totally cost (0.000011 second [0.011421 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000693 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000317 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] Search task load file id:921037 CPU2GPU:0 file type:1 size:0 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592142841055850000/1592142841055850000 totally cost (0.000009 second [0.009491 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000709 ms])
2020-06-15 09:52:04,801 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000362 second [0.361822 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000638 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000329 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] Search task load file id:918347 CPU2GPU:1 file type:3 size:145718483 bytes from location: /var/lib/milvus/db/tables/1591977144528510000/1592126799378535000/1592126802677400000 totally cost (0.000011 second [0.010607 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000700 ms])
2020-06-15 09:52:04,802 | DEBUG | default | [SERVER] Search task load file id:925706 CPU2GPU:1 file type:3 size:145802471 bytes from location: /var/lib/milvus/db/tables/1592060088341038000/1592168331065017000/1592168334150603000 totally cost (0.000010 second [0.010049 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] MySQLMetaImpl::Size: SELECT IFNULL(SUM(file_size),0) AS sum FROM TableFiles WHERE file_type <> 4;
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.001784 second [1.783912 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] get uids 286781 from index /var/lib/milvus/db/tables/1592060088341038000/1592185901761660000/1592185901761660000
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000053 second [0.052595 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] DoSearch file id:931852: job 5508290 nq 10 topk 5, do search (0.002205 second [2.204683 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] DoSearch file id:931852: job 5508290 nq 10 topk 5, reduce topk (0.000021 second [0.020543 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 931852
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] DoSearch file id:931852: totally cost (0.002248 second [2.248245 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000739 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000013 second [0.013375 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000790 ms])
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] Begin flush all tables
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] MemTable flush
2020-06-15 09:52:04,803 | DEBUG | default | [ENGINE] Flushing table: 1592060088341038000
2020-06-15 09:52:04,804 | DEBUG | default | [ENGINE] Initializing bloom filter took 0.000208521 s
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.003957 second [3.956656 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [ENGINE] get uids 444679 from index /var/lib/milvus/db/tables/1592060088341038000/1592177578927133000/1592177581891370000
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000025 second [0.024638 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] DoSearch file id:928300: job 5508290 nq 10 topk 5, do search (0.004434 second [4.434052 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] DoSearch file id:928300: job 5508290 nq 10 topk 5, reduce topk (0.000007 second [0.006580 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 928300
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] DoSearch file id:928300: totally cost (0.004451 second [4.451273 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000632 ms])
2020-06-15 09:52:04,805 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,805 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,805 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000007 second [0.006701 ms])
2020-06-15 09:52:04,806 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000715 ms])
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Adding 50 ids to bloom filter took 0.00350843 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing bloom filter took 7.628e-06 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing bloom filter took 0.00381756 s in total
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing raw vectors took 9.7693e-05 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing uids took 1.8096e-05 s
2020-06-15 09:52:04,807 | DEBUG | default | [ENGINE] Writing vectors and uids took 0.000255234 s in total
2020-06-15 09:52:04,808 | DEBUG | default | [ENGINE] Writing deleted docs took 0.000101255 s
2020-06-15 09:52:04,808 | DEBUG | default | [ENGINE] MySQLMetaImpl::UpdateTableFile: SELECT state FROM Tables WHERE table_id = '1592060088341038000';
2020-06-15 09:52:04,808 | DEBUG | default | [ENGINE] MySQLMetaImpl::UpdateTableFile: UPDATE TableFiles SET table_id = '1592060088341038000' ,engine_type = 3 ,file_id = '1592185924569713000' ,file_type = 1 ,file_size = 60400 ,row_count = 50 ,updated_time = 1592185924808111 ,created_on = 1592185924569715 ,date = 1200515 WHERE id = 931853;
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] Update single table file, file id = 1592185924569713000
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] New raw file 1592185924569713000 of size 60000 bytes, lsn = 0
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] Flushed segment 1592185924569713000
2020-06-15 09:52:04,809 | DEBUG | default | [ENGINE] MySQLMetaImpl::UpdateTableFlushLSN: UPDATE Tables SET flush_lsn = 0 WHERE table_id = '1592060088341038000';
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.004850 second [4.850397 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] get uids 445000 from index /var/lib/milvus/db/tables/1591977144528510000/1592093767724537000/1592093770722822000
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000025 second [0.025218 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] DoSearch file id:906800: job 5508290 nq 10 topk 5, do search (0.004896 second [4.895675 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] DoSearch file id:906800: job 5508290 nq 10 topk 5, reduce topk (0.000007 second [0.006757 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 906800
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] DoSearch file id:906800: totally cost (0.004913 second [4.912831 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000422 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000007 second [0.006822 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000665 ms])
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Successfully update table flush_lsn, table id = 1592060088341038000
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Finished flushing for table 1592060088341038000 in 0.00708644 s
2020-06-15 09:52:04,810 | DEBUG | default | [ENGINE] Flushed table: 1592060088341038000
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] End flush all tables
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] MySQLMetaImpl::DescribeTable: SELECT id, state, dimension, created_on, flag, index_file_size, engine_type, index_params , metric_type ,owner_table, partition_tag, version, flush_lsn FROM Tables WHERE table_id = '1592060088341038000' AND state <> 1;
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] MySQLMetaImpl::FilesToIndex: SELECT id, table_id, segment_id, engine_type, file_id, file_type, file_size, row_count, date, created_on FROM TableFiles WHERE file_type = 2;
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] MySQLMetaImpl::FilesToMerge: SELECT id, table_id, segment_id, file_id, file_type, file_size, row_count, date, engine_type, created_on FROM TableFiles WHERE table_id = '1592060088341038000' AND file_type = 1 ORDER BY row_count DESC;
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] Mark ongoing file:1592185901761660000 refcount:2
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] Mark ongoing file:1592185924569713000 refcount:1
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] Merge files for table: 1592060088341038000
2020-06-15 09:52:04,811 | DEBUG | default | [ENGINE] MySQLMetaImpl::DescribeTable: SELECT id, state, dimension, created_on, flag, index_file_size, engine_type, index_params , metric_type ,owner_table, partition_tag, version, flush_lsn FROM Tables WHERE table_id = '1592060088341038000' AND state <> 1;
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] MySQLMetaImpl::CreateTableFile: INSERT INTO TableFiles VALUES(NULL, '1592060088341038000', '1592185924812270000', 3, '1592185924812270000', 5, 0, 0, 1592185924812273, 1592185924812273, 1200515, 0);
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.008838 second [8.837506 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] get uids 444761 from index /var/lib/milvus/db/tables/1591977144528510000/1592085184848009000/1592085188124571000
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000033 second [0.033409 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] DoSearch file id:904659: job 5508290 nq 10 topk 5, do search (0.008910 second [8.909594 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] DoSearch file id:904659: job 5508290 nq 10 topk 5, reduce topk (0.000013 second [0.012605 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 904659
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] DoSearch file id:904659: totally cost (0.008948 second [8.947505 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] PickToExecute  (0.000001 second [0.000555 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,812 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000013 second [0.012585 ms])
2020-06-15 09:52:04,812 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000683 ms])
2020-06-15 09:52:04,813 | DEBUG | default | [ENGINE] Successfully create table file, file id = 1592185924812270000
2020-06-15 09:52:04,813 | DEBUG | default | [ENGINE] Merging from /var/lib/milvus/db/tables/1592060088341038000/1592185901761660000 to /var/lib/milvus/db/tables/1592060088341038000/1592185924812270000
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.007463 second [7.462992 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [ENGINE] get uids 444539 from index /var/lib/milvus/db/tables/1591977144528510000/1592126799378535000/1592126802677400000
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000030 second [0.029569 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] DoSearch file id:918347: job 5508290 nq 10 topk 5, do search (0.007513 second [7.512870 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] DoSearch file id:918347: job 5508290 nq 10 topk 5, reduce topk (0.000006 second [0.006290 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 918347
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] DoSearch file id:918347: totally cost (0.007530 second [7.529642 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000340 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,818 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000022 second [0.022294 ms])
2020-06-15 09:52:04,818 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000450 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.006896 second [6.896000 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [ENGINE] get uids 444645 from index /var/lib/milvus/db/tables/1591977144528510000/1592107448158549000/1592107451249160000
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000038 second [0.038466 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] DoSearch file id:912444: job 5508290 nq 10 topk 5, do search (0.006976 second [6.975739 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] DoSearch file id:912444: job 5508290 nq 10 topk 5, reduce topk (0.000013 second [0.012599 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 912444
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] DoSearch file id:912444: totally cost (0.007010 second [7.009756 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000450 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [ENGINE] Search job extra params: {"nprobe":16}
2020-06-15 09:52:04,819 | DEBUG | default | [ENGINE] Search params: {"k":5,"nprobe":16}
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search prepare (0.000012 second [0.012050 ms])
2020-06-15 09:52:04,819 | DEBUG | default | [SERVER] PickToLoad  (0.000001 second [0.000574 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.002527 second [2.527049 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [ENGINE] get uids 444796 from index /var/lib/milvus/db/tables/1592060088341038000/1592168331065017000/1592168334150603000
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000019 second [0.019248 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] DoSearch file id:925706: job 5508290 nq 10 topk 5, do search (0.002594 second [2.593900 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] DoSearch file id:925706: job 5508290 nq 10 topk 5, reduce topk (0.000006 second [0.006201 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 925706
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] DoSearch file id:925706: totally cost (0.002610 second [2.610342 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000151 ms])
2020-06-15 09:52:04,820 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000047 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000185 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: search done (0.001270 second [1.270468 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] get uids 201549 from index /var/lib/milvus/db/tables/1591977144528510000/1592142841055850000/1592142841055850000
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] ExecutionEngineImpl::Search float: map uids 50 (0.000083 second [0.083496 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] DoSearch file id:921037: job 5508290 nq 10 topk 5, do search (0.001403 second [1.403256 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] DoSearch file id:921037: job 5508290 nq 10 topk 5, reduce topk (0.000021 second [0.020977 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] SearchJob 5508290 finish index file: 921037
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] SearchJob 5508290 all done
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] DoSearch file id:921037: totally cost (0.001480 second [1.479862 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592085188124571000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] PickToExecute  (0.000000 second [0.000464 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592093770722822000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [SERVER] PickToLoad  (0.000000 second [0.000403 ms])
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592107451249160000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592126802677400000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592142841055850000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592168334150603000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592177581891370000 refcount:0
2020-06-15 09:52:04,821 | DEBUG | default | [ENGINE] Unmark ongoing file:1592185901761660000 refcount:1

...

2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592085188124571000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592093770722822000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592107451249160000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592126802677400000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592142841055850000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592168334150603000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592177581891370000 refcount:1
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592185901761660000 refcount:2
2020-06-15 09:52:05,464 | DEBUG | default | [ENGINE] Mark ongoing file:1592185924569713000 refcount:2

...

2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592093770722822000 refcount:0
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592107451249160000 refcount:0
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592126802677400000 refcount:0
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592142841055850000 refcount:0
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592168334150603000 refcount:0
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592177581891370000 refcount:0
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592185901761660000 refcount:1
2020-06-15 09:52:05,762 | DEBUG | default | [ENGINE] Unmark ongoing file:1592185924569713000 refcount:1
@yhmo
Copy link
Contributor

yhmo commented Jun 16, 2020

The log "xxx is currently in use, not able to delete now" means the file is used by a search request, and the background cleanup thread could not delete until the search request finish.

Before the server hangs, does it continually receive vectors and search request?
Could you find out the last 500 lines of debug log before the server hangs and shutdown?

@tinkerlin tinkerlin added the kind/support Issues that users need help label Jun 17, 2020
@chenrulongmaster
Copy link
Author

chenrulongmaster commented Jun 17, 2020 •
edited
Loading

Yes, the inserts and search happens continually.
Pls check the log file below. Thx
milvus_debug.zip

@yhmo

@yhmo
Copy link
Contributor

yhmo commented Jun 18, 2020 •
edited
Loading

Hi chenrulongmaster,
Could you find out the xxx.info.log and send to me?
And a few questions:

  1. How many collections/partitions in you scenario?
  2. Did you use multi-thread or multi-client to insert data into different collection/partition?

@yhmo
Copy link
Contributor

yhmo commented Jun 20, 2020 •
edited
Loading

May caused by #2640(which was fixed by #2641 in 0.10.1 branch)

@yhmo
Copy link
Contributor

yhmo commented Jul 3, 2020

Another hang issue #2692(which was fixed by #2715 in 0.10.1), is very similar to this issue.

@yhmo
Copy link
Contributor

yhmo commented Jul 3, 2020

link to #2692

@shengjun1985
Copy link
Contributor

It is fixed in the later version.
Thank you for your concern and support for our project.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@yhmo yhmo

Labels
kind/support Issues that users need help
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@yhmo @tinkerlin @chenrulongmaster @shengjun1985