clickhouse-go icon indicating copy to clipboard operation
clickhouse-go copied to clipboard

Can't insert value processed by function

Open dmmarkov opened this issue 3 years ago • 8 comments

Hello!

Issue description

I want insert DateTime value rounded to lower 15 minutes. I use this query insert into test (rounded_time) values (toStartOfFifteenMinutes(:rounded_time)). Insert works, but in the table I see value of rounded_time without applying of toStartOfFifteenMinutes.

In the clickhouse-client query insert into test (rounded_time) values (toStartOfFifteenMinutes(now())) works fine.

Why driver don't understand toStartOfFifteenMinutes in query?

Error log

No errors.

Configuration

OS: linux

Interface: native, sqlx

Driver version: v2 or v1 - it doesn't matter

Go version: 1.18.3

ClickHouse Server version: 22.1.3.7-alpine

dmmarkov avatar Aug 04 '22 10:08 dmmarkov

look to SELECT * FROM system.query_log FORMAT Vertical and try to figure out which query passed from clickhouse-go to clickhouse-server

Slach avatar Aug 04 '22 10:08 Slach

Sample code

package main

import (
	"context"
	"fmt"
	"net/url"
	"time"

	_ "github.com/ClickHouse/clickhouse-go/v2" // clickhouse driver
	"github.com/jmoiron/sqlx"
	"github.com/sirupsen/logrus"
)

const (
	dbHost = "localhost"
	dbPort = 9000
	query  = `
		insert into test (
			raw_time,
			rounded_time
		) values (
			:raw_time,
			toStartOfFifteenMinutes(:raw_time)
		)
	`
)

func main() {
	conn, err := sqlx.Connect("clickhouse", ClickhouseURI())
	if err != nil {
		logrus.Panicf("connect failed: %s", err)
	}

	ctx := context.Background()

	tx, err := conn.BeginTxx(ctx, nil)
	if err != nil {
		logrus.Panicf("conn.BeginTxx(...) failed: %s", err)
	}

	stmt, err := tx.PrepareNamedContext(ctx, query)
	if err != nil {
		logrus.Panicf("tx.PrepareNamedContext(...) failed: %s", err)
	}

	args := map[string]interface{}{
		"raw_time": time.Now(),
	}

	if _, err := stmt.ExecContext(ctx, args); err != nil {
		logrus.Panicf("stmt.ExecContext(...) failed (%T %v): %s", args, args, err)
	}

	if err := tx.Commit(); err != nil {
		logrus.Panicf("tx.Commit(...) failed: %s", err)
	}

	logrus.Info("check record in db")
}

func ClickhouseURI() string {
	dsnURL := url.URL{
		Scheme: "tcp",
		Host:   fmt.Sprintf("%s:%d", dbHost, dbPort),
	}

	return dsnURL.String()
}

Create table SQL

CREATE TABLE default.test
(
    `raw_time` DateTime,
    `rounded_time` DateTime
)
ENGINE = MergeTree
ORDER BY raw_time

dmmarkov avatar Aug 04 '22 10:08 dmmarkov

SELECT * FROM system.query_log FORMAT Vertical

I found only this rows

Row 1:
──────
type:                                  QueryStart
event_date:                            2022-08-04
event_time:                            2022-08-04 10:29:05
event_time_microseconds:               2022-08-04 10:29:05.187913
query_start_time:                      2022-08-04 10:29:05
query_start_time_microseconds:         2022-08-04 10:29:05.187913
query_duration_ms:                     0
read_rows:                             0
read_bytes:                            0
written_rows:                          0
written_bytes:                         0
result_rows:                           0
result_bytes:                          0
memory_usage:                          0
current_database:                      default
query:                                 
                insert into test (
                        raw_time,
                        rounded_time
                ) VALUES
formatted_query:                       
normalized_query_hash:                 9074919209337887203
query_kind:                            Insert
databases:                             ['default']
tables:                                ['default.test']
columns:                               []
projections:                           []
views:                                 []
exception_code:                        0
exception:                             
stack_trace:                           
is_initial_query:                      1
user:                                  default
query_id:                              16a94cb7-21e1-4fb1-a3e0-dda7af053f4d
address:                               ::ffff:172.28.0.1
port:                                  44962
initial_user:                          default
initial_query_id:                      16a94cb7-21e1-4fb1-a3e0-dda7af053f4d
initial_address:                       ::ffff:172.28.0.1
initial_port:                          44962
initial_query_start_time:              2022-08-04 10:29:05
initial_query_start_time_microseconds: 2022-08-04 10:29:05.187913
interface:                             1
os_user:                               dmitri
client_hostname:                       localhost.localdomain
client_name:                           Golang SQLDriver
client_revision:                       54453
client_version_major:                  1
client_version_minor:                  1
client_version_patch:                  0
http_method:                           0
http_user_agent:                       
http_referer:                          
forwarded_for:                         
quota_key:                             
revision:                              54458
log_comment:                           
thread_ids:                            []
ProfileEvents:                         {}
Settings:                              {'receive_timeout':'1800','send_timeout':'1800','load_balancing':'random','max_memory_usage':'10000000000'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               []
used_dictionaries:                     []
used_formats:                          []
used_functions:                        []
used_storages:                         []
used_table_functions:                  []

Row 2:
──────
type:                                  QueryFinish
event_date:                            2022-08-04
event_time:                            2022-08-04 10:29:05
event_time_microseconds:               2022-08-04 10:29:05.189321
query_start_time:                      2022-08-04 10:29:05
query_start_time_microseconds:         2022-08-04 10:29:05.187913
query_duration_ms:                     1
read_rows:                             0
read_bytes:                            0
written_rows:                          1
written_bytes:                         8
result_rows:                           1
result_bytes:                          1
memory_usage:                          4259355
current_database:                      default
query:                                 
                insert into test (
                        raw_time,
                        rounded_time
                ) VALUES
formatted_query:                       
normalized_query_hash:                 9074919209337887203
query_kind:                            Insert
databases:                             ['default']
tables:                                ['default.test']
columns:                               []
projections:                           []
views:                                 []
exception_code:                        0
exception:                             
stack_trace:                           
is_initial_query:                      1
user:                                  default
query_id:                              16a94cb7-21e1-4fb1-a3e0-dda7af053f4d
address:                               ::ffff:172.28.0.1
port:                                  44962
initial_user:                          default
initial_query_id:                      16a94cb7-21e1-4fb1-a3e0-dda7af053f4d
initial_address:                       ::ffff:172.28.0.1
initial_port:                          44962
initial_query_start_time:              2022-08-04 10:29:05
initial_query_start_time_microseconds: 2022-08-04 10:29:05.187913
interface:                             1
os_user:                               dmitri
client_hostname:                       localhost.localdomain
client_name:                           Golang SQLDriver
client_revision:                       54453
client_version_major:                  1
client_version_minor:                  1
client_version_patch:                  0
http_method:                           0
http_user_agent:                       
http_referer:                          
forwarded_for:                         
quota_key:                             
revision:                              54458
log_comment:                           
thread_ids:                            [46]
ProfileEvents:                         {'Query':1,'InsertQuery':1,'FileOpen':7,'WriteBufferFromFileDescriptorWrite':7,'WriteBufferFromFileDescriptorWriteBytes':425,'IOBufferAllocs':14,'IOBufferAllocBytes':3241984,'DiskWriteElapsedMicroseconds':36,'NetworkReceiveElapsedMicroseconds':330,'NetworkSendElapsedMicroseconds':40,'NetworkReceiveBytes':72,'NetworkSendBytes':136,'InsertedRows':1,'InsertedBytes':8,'MergeTreeDataWriterRows':1,'MergeTreeDataWriterUncompressedBytes':8,'MergeTreeDataWriterCompressedBytes':149,'MergeTreeDataWriterBlocks':1,'MergeTreeDataWriterBlocksAlreadySorted':1,'ContextLock':16,'RWLockAcquiredReadLocks':2,'RealTimeMicroseconds':1463,'UserTimeMicroseconds':256,'SystemTimeMicroseconds':857,'SoftPageFaults':12,'OSCPUVirtualTimeMicroseconds':1112,'OSWriteBytes':28672,'OSReadChars':414,'OSWriteChars':1652}
Settings:                              {'receive_timeout':'1800','send_timeout':'1800','load_balancing':'random','max_memory_usage':'10000000000'}
used_aggregate_functions:              []
used_aggregate_function_combinators:   []
used_database_engines:                 []
used_data_type_families:               ['DateTime']
used_dictionaries:                     []
used_formats:                          []
used_functions:                        ['replicate']
used_storages:                         []
used_table_functions:                  []

dmmarkov avatar Aug 04 '22 10:08 dmmarkov

I suspect i know why this is happening - the PrepareNamedContext is effectively building a batch. It expects the VALUES to be passed as part of the Exec not as part of PrepareNamedContext.

Try,

conn.Exec("insert into test (raw_time, rounded_time) values (:raw_time, toStartOfFifteenMinutes(:raw_time))")

and don't build a batch. The batch logic isn't sending the function - only using it to determine the column type. I'll try and add a test here later.

gingerwizard avatar Aug 11 '22 08:08 gingerwizard

@gingerwizard seems like the batch behavior should be handled by the callers. What if you want to...

INSERT INTO foo SELECT * FROM bar

Or:

INSERT INTO FOO FORMAT JSONEachRow { "key1": "foo", "key2": "bar" }

The current behavior prevents all sorts of expressions by being too clever. Batching on the caller side seems easy enough.

chancez avatar Aug 22 '22 21:08 chancez

Apologies i meant to take a look at this.

You can't insert using JSONEachRow since we use native format by design - this isn't clickhouse-client. We're opinionated on the insert format itself in effect.

Neither of the above examples are candidates for the batch functionality really - these can be achieved using Exec.

Not quite sure what you mean by "batching on the caller side"? Can you elaborate?

The batch functionality is designed to give us a block we can assemble on the client side based on the target columns. I think the original example can be achieved by just preserving the full INSERT statement with expressions when sending this to clickhouse - which in turn responds with the column types its expecting.

gingerwizard avatar Aug 22 '22 23:08 gingerwizard

We're inserting in a transaction and previously were seeing when trying to insert outside a transaction:

insert statement supported only in the batch mode (use begin/commit)

chancez avatar Aug 23 '22 14:08 chancez

Without batch my Insert statement works as expected.

But I need to use batch, because I have a lot of rows to insert.

I understand that I should prepare data before insert. It's just a bit unexpected, but I can manage it.

Thanks for answers.

dmmarkov avatar Sep 20 '22 14:09 dmmarkov