[MCOL-5411] Insert Failed: Failed to flush list of blocks from PrimProc cache. Created: 2023-02-01  Updated: 2023-11-17

Status: Open
Project: MariaDB ColumnStore
Component/s: DMLProc
Affects Version/s: 6.2.3
Fix Version/s: Icebox

Type: Bug Priority: Critical
Reporter: Allen Lee (Inactive) Assignee: Unassigned
Resolution: Unresolved Votes: 1
Labels: None
Environment:

CentOS Linux release 7.8.2003 (Core)
4.20.11-1.el7.elrepo.x86_64


 Description   

There are several occasions where the customer hit 'Insert Failed: Failed to flush list of blocks from PrimProc cache.' when importing data. The error message is not very helpful as it does not explain why this is happening.

Case1.

2023-01-16T22:13:06.867574+09:00 db-airis102 ddlpackageproc[18512]: 06.867422 |33593458|723574|0| D 23 CAL0041: Start SQL statement: CREATE TABLE ci2_prod.`AIris_DEMO$38938$original` (#012#011easy_id BIGINT#012)ENGINE=Columnstore DEFAULT CHARSET=UTF8;|ci2_prod|
 
2023-01-16T22:13:07.950151+09:00 db-airis102 ddlpackageproc[18512]: 07.949930 |33593458|723574|0| D 23 CAL0042: End SQL statement
 
2023-01-16T22:13:08.717544+09:00 db-airis102 ExeMgr[18439]: 08.717423 |2181077106|0|0| D 16 CAL0041: Start SQL statement: select objectid from systable where schema='ci2_prod' and tablename='AIris_DEMO$38938$original' --tableRID/; ||
 
2023-01-16T22:13:08.956207+09:00 db-airis102 ExeMgr[18439]: 08.956058 |2181077106|0|0| D 16 CAL0042: End SQL statement
 
2023-01-16T22:13:25.067443+09:00 db-airis102 dmlpackageproc[18474]: 25.067116 |33593458|723575|0| D 21 CAL0001: End SQL statement with error
 
2023-01-16T22:13:25.067789+09:00 db-airis102 dmlpackageproc[18474]: 25.067480 |0|0|0| E 21 CAL0001: Insert Failed:   Failed to flush list of blocks from PrimProc cache.
 
2023-01-16T22:13:25.090602+09:00 db-airis102 dmlpackageproc[18474]: 25.090418 |33593458|723575|0| D 21 CAL0001: Start SQL statement:  ROLLBACK
 
2023-01-16T22:13:27.036100+09:00 db-airis102 writeengine[18465]: 27.035914 |0|0|0| I 19 CAL0084: ClearTableLock: Starting bulk rollback for table ci2_prod.AIris_DEMO$38938$original (OID-3188646); lock-24555; initiated by BatchInsert.
 
2023-01-16T22:13:27.036278+09:00 db-airis102 writeengine[18465]: 27.036028 |0|0|0| I 19 CAL0072: ClearTableLock: Rollback extents   for table ci2_prod.AIris_DEMO$38938$original (OID-3188646).
 
2023-01-16T22:13:27.037074+09:00 db-airis102 writeengine[18465]: 27.036983 |0|0|0| I 19 CAL0090: ClearTableLock: Nothing to rollback for table ci2_prod.AIris_DEMO$38938$original (OID-3188646) on DBRoot1
 
2023-01-16T22:13:27.037318+09:00 db-airis102 writeengine[18465]: 27.037004 |0|0|0| I 19 CAL0085: ClearTableLock: Ending bulk rollback for table ci2_prod.AIris_DEMO$38938$original (OID-3188646); lock-24555; initiated by BatchInsert. (Nothing to rollback).
 
2023-01-16T22:13:27.042382+09:00 db-airis102 dmlpackageproc[18474]: 27.042269 |33593458|723575|0| D 21 CAL0001: End SQL statement
 
2023-01-16T22:13:27.066685+09:00 db-airis102 dmlpackageproc[18474]: 27.066574 |33593458|0|0| D 21 CAL0001: Start SQL statement:  ROLLBACK
 
2023-01-16T22:13:27.066793+09:00 db-airis102 dmlpackageproc[18474]: 27.066619 |33593458|0|0| D 21 CAL0001: End SQL statement

Case2.

2023-01-16T22:39:23.177915+09:00 db-airis102 ExeMgr[18439]: 23.177784 |33593596|0|0| D 16 CAL0041: Start SQL statement: SELECT ci2_prod.`AIris_DEMO$38944$purchase_hist`.g1, ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn1, ci2_prod.`AIris_DEMO$38944$purchase_hist`.g2, ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn2, ci2_prod.`AIris_DEMO$38944$purchase_hist`.g3, ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn3, count(DISTINCT ci2_prod.`AIris_DEMO$38944$purchase_hist`.easy_id) AS easy_ids, (SELECT count(DISTINCT ci2_prod.`AIris_DEMO$38944$purchase_hist`.easy_id) AS count_1 #012FROM ci2_prod.`AIris_DEMO$38944$purchase_hist`) AS total #012FROM ci2_prod.`AIris_DEMO$38944$purchase_hist` #012WHERE ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn3 IS NOT NULL AND ci2_prod.`AIris_DEMO$38944$purchase_hist`.easy_id >= 0 GROUP BY ci2_prod.`AIris_DEMO$38944$purchase_hist`.g1, ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn1, ci2_prod.`AIris_DEMO$38944$purchase_hist`.g2, ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn2, ci2_prod.`AIris_DEMO$38944$purchase_hist`.g3, ci2_prod.`AIris_DEMO$38944$purchase_hist`.gn3 ORDER BY easy_ids DESC #012 LIMIT 20; |airis|
 
2023-01-16T22:39:23.197113+09:00 db-airis102 dbcon[11468]: 23.196983 |33593606|0|0| D 24 CAL0001: End SQL statement
 
2023-01-16T22:39:32.630085+09:00 db-airis102 ddlpackageproc[18512]: 32.629879 |33593598|723614|0| D 23 CAL0041: Start SQL statement: CREATE TABLE ci2_prod.`Joseph$38947$purchase_hist` (#012#011easy_id INTEGER, #012#011sub_total_amt INTEGER, #012#011g1 INTEGER, #012#011gn1 VARCHAR(100), #012#011g2 INTEGER, #012#011gn2 VARCHAR(100), #012#011g3 INTEGER, #012#011gn3 VARCHAR(100), #012#011g4 INTEGER, #012#011gn4 VARCHAR(100), #012#011g5 INTEGER, #012#011gn5 VARCHAR(100)#012)ENGINE=Columnstore DEFAULT CHARSET=UTF8;|ci2_prod|
 
2023-01-16T22:39:35.018040+09:00 db-airis102 ddlpackageproc[18512]: 35.017833 |33593598|723614|0| D 23 CAL0042: End SQL statement
 
2023-01-16T22:39:35.021320+09:00 db-airis102 ExeMgr[18439]: 35.021200 |2181077246|0|0| D 16 CAL0041: Start SQL statement: select objectid,columnname from syscolumn where schema='ci2_prod' and tablename='Joseph$38947$purchase_hist' --columnRIDs/FE; ||
 
2023-01-16T22:39:36.206858+09:00 db-airis102 ExeMgr[18439]: 36.206625 |2181077246|0|0| D 16 CAL0042: End SQL statement
 
2023-01-16T22:39:36.207043+09:00 db-airis102 dbcon[11468]: 36.206905 |33593598|0|0| D 24 CAL0001: Start SQL statement: INSERT INTO ci2_prod.`Joseph$38947$purchase_hist` (easy_id, sub_total_amt, g1, gn1, g2, gn2, g3, gn3, g4, gn4, g5, gn5) SELECT airis.purchase_history_mst.easy_id, airis.purchase_history_mst.sub_total_amt, airis.purchase_history_mst.g1, airis.purchase_history_mst.gn1, airis.purchase_history_mst.g2, airis.purchase_history_mst.gn2, airis.purchase_history_mst.g3, airis.purchase_history_mst.gn3, airis.purchase_history_mst.g4, airis.purchase_history_mst.gn4, airis.purchase_history_mst.g5, airis.purchase_history_mst.gn5 #012FROM airis.purchase_history_mst #012WHERE EXISTS (SELECT DISTINCT ci2_prod.`Joseph$38947$seed`.easy_id #012FROM ci2_prod.`Joseph$38947$seed` #012WHERE airis.purchase_history_mst.easy_id = ci2_prod.`Joseph$38947$seed`.easy_id); |ci2_prod|
 
2023-01-16T22:39:36.252399+09:00 db-airis102 ExeMgr[18439]: 36.252246 |2181077246|0|0| D 16 CAL0041: Start SQL statement: select objectid from systable where schema='ci2_prod' and tablename='Joseph$38947$purchase_hist' --tableRID/; ||
 
2023-01-16T22:39:36.356149+09:00 db-airis102 dmlpackageproc[18474]: 36.355850 |33593634|723613|0| D 21 CAL0001: End SQL statement with error
 
2023-01-16T22:39:36.356810+09:00 db-airis102 dmlpackageproc[18474]: 36.356522 |0|0|0| E 21 CAL0001: Insert Failed:   Failed to flush list of blocks from PrimProc cache.
 
2023-01-16T22:39:36.382157+09:00 db-airis102 dmlpackageproc[18474]: 36.382027 |33593634|723613|0| D 21 CAL0001: Start SQL statement:  ROLLBACK
 
2023-01-16T22:39:36.505760+09:00 db-airis102 ExeMgr[18439]: 36.505428 |2181077246|0|0| D 16 CAL0042: End SQL statement

Please see more errors in the attachments.

 Comments   
Comment by Mindaugas Liubinas [ 2023-05-07 ]

Package: MariaDB-columnstore-engine.x86_64 10.6.12_6.4.7-1.el7.centos

Same error while inserting data using DML (INSERT INTO ....)

{{May 7 06:29:41 vault dmlpackageproc[11586]: 41.293406 |23397|443583|0| D 21 CAL0001: End SQL statement
May 7 06:29:41 vault dmlpackageproc[11586]: 41.315384 |23397|443583|0| D 21 CAL0001: Start SQL statement: COMMIT
May 7 06:29:41 vault dmlpackageproc[11586]: 41.350837 |23397|443583|0| D 21 CAL0001: End SQL statement
May 7 06:29:51 vault dmlpackageproc[11586]: 51.086971 |23397|443584|0| D 21 CAL0001: End SQL statement
May 7 06:29:51 vault dmlpackageproc[11586]: 51.113576 |23397|443584|0| D 21 CAL0001: Start SQL statement: COMMIT
May 7 06:29:51 vault dmlpackageproc[11586]: 51.157425 |23397|443584|0| D 21 CAL0001: End SQL statement
May 7 06:30:01 vault dmlpackageproc[11586]: 01.853589 |23397|443585|0| D 21 CAL0001: End SQL statement
May 7 06:30:01 vault dmlpackageproc[11586]: 01.880885 |23397|443585|0| D 21 CAL0001: Start SQL statement: COMMIT
May 7 06:30:01 vault dmlpackageproc[11586]: 01.922255 |23397|443585|0| D 21 CAL0001: End SQL statement
May 7 06:30:23 vault dmlpackageproc[11586]: 23.382751 |23397|443586|0| D 21 CAL0001: End SQL statement with error
May 7 06:30:23 vault dmlpackageproc[11586]: 23.383760 |0|0|0| E 21 CAL0006: Failed to flush list of blocks from PrimProc cache. }}

Generated at Thu Feb 08 02:57:41 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.