<foreach> and postgresql log

[abalo...@gilt.jp]

Hello,

I am using the mybatis <foreach> statement in one of my sql queries. mybatis generates a prepared statement that I can see in the logs:

select ...
from products p
join product_categories pc on pc.id = p.product_category_id
(many more joins)
where p.id in ( ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ...)

==> Parameters: 18310573(Long), 44478123(Long), 17805559(Long), 41610962(Long), 16733361(Long), 51136262(Long), 18676625(Long), 17242776(Long), 17322051(Long), 17322031(Long), 43392127(Long), 17338259(Long), 16738428(Long), 17203169(Long), 16896876(Long), 16726746(Long), 44478130(Long), 18733088(Long), 18572799(Long), 44478138(Long),....

Everything is working fine even though the query contains many joins and a long list of parameters that I have truncated to avoid filling the space unnecessarily.

I also have to tell you that we log slow queries at the postgresql level with the following option log_min_duration_statement.

The problem comes from the fact that either mybatis generates a sql query with one parameter per line or postgresql logs the query with one parameter per line. 

Here is how the query is logged in the postgresql logs:

select ...
from products p
join product_categories pc on pc.id = p.product_category_id
(many more joins)
where p.id in ( 18310573,
                44478123,
                17805559,
                41610962,
                16733361,
                ....)
 

This doesn't seem to be a big problem but with half a million products which I have to query entirely on a regular basis I end up with gigabytes of logs whether I query in batch (of 1000) or not it's almost the same result obviously.

I am actually writing code in Scala using mybatis-scala (version: 1.0.3) which uses mybatis (version: 3.2.8). The postgresql version is 9.2.

I have been reading the source code of both mybatis-scala and mybatis without being able to figure out where the problem comes from. I got a bit lost in the code of mybatis to be honest. 

I think that the code generating the actual sql query with parameter is in the following method: 

public BoundSql getBoundSql(Object parameterObject)

Also, I can see the prepared statement in the logs of mybatis but not the actual query that is executed on postgresql. pg_stat_activity unfortunately truncates the query so I cannot see the raw query before it is being logged. 

I am assuming that there might be some preprocessing before logging although I would be surprise if postgresql split the params on multiple lines. To be honest I suspect that mybatis foreach generates the query with one line per parameter but I am not sure.

Is there a kind-hearted person who could enlighten me? (Is there anyone that actually read until here? :-) )

Thank you in advance,

Alexandre

[Guy Rouillier]

You forgot to mention the most important part: how you are defining the query in MyBatis.  For example, if your foreach is formatted like this:

 

    <foreach collection="myList" item="item" open="(" separator="," close=")">
    #{item, jdbcType=INTEGER}
    </foreach>

Then that is where your newline is coming from.  You can avoid that by simply putting everything shown above on a single line.

 

However, this is probably not where your "gigabytes of logs" are coming from.  To put each parameter on a separate line only requires the parameter to be followed by a newline character, which is either 1 (Linux) or 2 (Windows) bytes.  To indent each parameter requires white space: make sure you are using tabs instead of spaces.

 

--

Guy Rouillier

--
You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mybatis-user...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

---

This email has been checked for viruses by Avast antivirus software. www.avast.com

[Jose María Zaragoza]

2015-07-25 2:34 GMT+02:00 Guy Rouillier <guy.ro...@gmail.com>:

You forgot to mention the most important part: how you are defining the query in MyBatis.  For example, if your foreach is formatted like this:

 

    <foreach collection="myList" item="item" open="(" separator="," close=")">
    #{item, jdbcType=INTEGER}
    </foreach>

Then that is where your newline is coming from.  You can avoid that by simply putting everything shown above on a single line.

I'm not sure. Why ?

JDBC client logs show this parametrized query 

select ...
from products p
join product_categories pc on pc.id = p.product_category_id
(many more joins)

where p.id in ( ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? ,? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? ,? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? ,? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ...)

I guess that query is sent as is

Logging framework could truncate blanks , but in this case, the query would be 

select ... from products p .....

I've to do the silly question of the day :

Could your text editor is formatting logs lines when you are reading it ?

Anyway, if you compress ( you should ) your logs, this problem should be solved

Regards

[abalo...@gilt.jp]

Thank you both for your quick replies.

@Guy: 

You are right I haven't posted the foreach part. 

<if collection="list" test="list != null">
  p.id in
  <foreach item="item" collection="list" open="(" separator="," close=")">
    { "item"? }
  </foreach>
</if>

Are you saying that if I do the following instead it will work?

<if collection="list" test="list != null">
  p.id in <foreach item="item" collection="list" open="(" separator="," close=")">{ "item"? }</foreach>
</if>

I haven't though about that at all since I was expecting mybatis to format according to the separator which is "," and not ",\n".

It's a good point though I will try asap and let you know! :)

@Jose Maria:

I am just tailing the logs as they are being written on so I don't think this is an editor problem but thank you for your input anyway. :)

Cheers,

Alexandre

BTW, I was wondering why not using Github for questions as well as issues since it is possible to add a "question" label?

The markdown formatting on Github is quite powerful compared to Google groups and it's relatively easy to see if the question has found a final answer by checking the closed ones although it could be better. Also Google groups are quite slow. Anyways, it might be best to open another thread on that subject! :)

On Friday, July 24, 2015 at 11:27:30 PM UTC+9, abalo...@gilt.jp wrote:

Hello,

I am using the mybatis <foreach> statement in one of my sql queries. mybatis generates a prepared statement that I can see in the logs:

select ...
from products p
join product_categories pc on pc.id = p.product_category_id
(many more joins)
where p.id in ( ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ? , ...)

==> Parameters: 18310573(Long), 44478123(Long), 17805559(Long), 41610962(Long), 16733361(Long), 51136262(Long), 18676625(Long), 17242776(Long), 17322051(Long), 17322031(Long), 43392127(Long), 17338259(Long), 16738428(Long), 17203169(Long), 16896876(Long), 16726746(Long), 44478130(Long), 18733088(Long), 18572799(Long), 44478138(Long),....

Everything is working fine even though the query contains many joins and a long list of parameters that I have truncated to avoid filling the space unnecessarily.

I also have to tell you that we log slow queries at the postgresql level with the following option log_min_duration_statement.

The problem comes from the fact that either mybatis generates a sql query with one parameter per line or postgresql logs the query with one parameter per line. 

Here is how the query is logged in the postgresql logs:

select ...
from products p
join product_categories pc on pc.id = p

...

[abalo...@gilt.jp]

The one liner fixed the problem of new line! :)

To improve the query, I switched from using the foreach to using boundaries which seems also more efficient on the db side:

and{ ?("uBound", jdbcType = JdbcType.INTEGER) }
> pl.id
and pl.id >={ ?("lBound", jdbcType = JdbcType.INTEGER) }

The "less than" and "more than" are a bit tricky. For some reason, mybatis crashes when I use &lt; and &gt; or &lteq; and &gteq;. Anyways, reversing the condition to only use ">" instead of "<" seems to be working fine.

Thank you again for your help!

[Guy Rouillier]

You can use CDATA to escape the < and > symbols:

 

    where x <![CDATA[ >= ]]> y

 

If you have several such symbols, you can just wrap your entire query in CDATA.

 

 

--

Guy Rouillier

 

 

 

------ Original Message ------

From: abalo...@gilt.jp

To: "mybatis-user" <mybati...@googlegroups.com>

--

You received this message because you are subscribed to the Google Groups "mybatis-user" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mybatis-user...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.