search

mybatis / mybatis-3

MyBatis SQL mapper framework for Java
http://mybatis.github.io/mybatis-3/
Apache License 2.0
19.74k stars 12.83k forks source link

SELECT count(*) hangs indefinitely when run from mybatis app context #2849

Closed ghevge closed 1 year ago

ghevge commented 1 year ago

When I run a complex SELECT count(*) query on a postgresql DB from my spring boot mybatis application, the query hangs, and never returns.

If I run the same query against the same DB, but using DBeaver functionality, the query returns in ~ 300 milliseconds. So it doesn't seem to be something wrong with the DB.

My app is a Java 17, spring boot postgresql application with the following versions:

<springboot.version>3.0.4</springboot.version>
        <hikariCP.version>5.0.1</hikariCP.version>
        <postgresql.driver.version>42.5.4</postgresql.driver.version>
        <mybatis.version>3.5.13</mybatis.version>
        <mybatis.spring.version>3.0.1</mybatis.spring.version>
        <mybatis.spring.boot.starter.version>3.0.1</mybatis.spring.boot.starter.version>

The logs that my app are generating when sending this query are:

middleware_1  | 2023-03-13T16:55:50.416Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.springframework.web.servlet.DispatcherServlet] org.springframework.web.servlet.DispatcherServletrlf(GET "/search?lm=10&s=tt&o=0&lc=en&la=45.4906639&lg=-73.4654282&dk=5&a=4", parameters={masked}) 
middleware_1  | 2023-03-13T16:55:50.417Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping] org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMappingrlf(Mapped to com.test.mw.controllers.SearchController#search(String, Integer, Integer, List, String, Double, Double, Double, List, List, List, List, List, List, List, Integer, List, Integer, Integer, UserDBO)) 
middleware_1  | 2023-03-13T16:55:50.420Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.springframework.jdbc.support.JdbcTransactionManager] org.springframework.jdbc.support.JdbcTransactionManagerrlf(Creating new transaction with name [com.test.mw.services.SearchService.search]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT) 
middleware_1  | 2023-03-13T16:55:50.421Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.springframework.jdbc.support.JdbcTransactionManager] org.springframework.jdbc.support.JdbcTransactionManagerrlf(Acquired Connection [HikariProxyConnection@587237285 wrapping org.postgresql.jdbc.PgConnection@5189b047] for JDBC transaction) 
middleware_1  | 2023-03-13T16:55:50.421Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.springframework.jdbc.support.JdbcTransactionManager] org.springframework.jdbc.support.JdbcTransactionManagerrlf(Switching JDBC Connection [HikariProxyConnection@587237285 wrapping org.postgresql.jdbc.PgConnection@5189b047] to manual commit) 
middleware_1  | 2023-03-13T16:55:50.423Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.mybatis.spring.SqlSessionUtils] org.mybatis.spring.SqlSessionUtilsrlf(Creating a new SqlSession) 
middleware_1  | 2023-03-13T16:55:50.423Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.mybatis.spring.SqlSessionUtils] org.mybatis.spring.SqlSessionUtilsrlf(Registering transaction synchronization for SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@2dc76db5]) 
middleware_1  | 2023-03-13T16:55:50.425Z <> {thread=http-nio-8080-exec-2} DEBUG: [org.mybatis.spring.transaction.SpringManagedTransaction] org.mybatis.spring.transaction.SpringManagedTransactionrlf(JDBC Connection [HikariProxyConnection@587237285 wrapping org.postgresql.jdbc.PgConnection@5189b047] will be managed by Spring) 
middleware_1  | 2023-03-13T16:55:50.425Z <> {thread=http-nio-8080-exec-2} DEBUG: [com.test.mw.db.mappers.SearchMapper.getSearchProductsCount] com.test.mw.db.mappers.SearchMapper.getSearchProductsCountrlf(==>  Preparing: SELECT count(*) FROM products p LEFT JOIN products_locations pl ON pl.product_id = p.id AND (pl.latitude <= ? OR pl.latitude IS NULL) AND (pl.latitude >= ? OR pl.latitude IS NULL) AND (pl.longitude <= ? OR pl.longitude IS NULL) AND (pl.longitude >= ? OR pl.longitude IS NULL) LEFT JOIN products_descriptions pd ON pd.product_id = p.id AND pd.locale = ? WHERE 1 = 1 AND p.id IN ( (SELECT id FROM products WHERE universal_product_code ILIKE ? OR model ILIKE ? OR isbn ILIKE ?) UNION (SELECT product_id FROM products_descriptions WHERE (title ILIKE ? OR description ILIKE ? OR ts_title @@ websearch_to_tsquery(?::regconfig, ?) OR ts_description @@ websearch_to_tsquery(?::regconfig, ?)) AND locale = ? ) UNION (SELECT product_id FROM products_contents WHERE content_id IN (SELECT id FROM contents WHERE (value ILIKE ? OR ts_value @@ websearch_to_tsquery(?::regconfig, ?)) AND locale = ? )) UNION (SELECT product_id FROM products_tags WHERE tag_id IN (SELECT id FROM tags WHERE (value ILIKE ? OR ts_value @@ websearch_to_tsquery(?::regconfig, ?)) AND locale = ? )) UNION (SELECT product_id FROM products_labels WHERE label_id IN (SELECT id FROM labels WHERE (value ILIKE ? OR ts_value @@ websearch_to_tsquery(?::regconfig, ?)) AND locale = ? )) UNION (SELECT product_id FROM products_brands WHERE brand_id IN (SELECT id FROM brands WHERE (value ILIKE ? OR ts_value @@ websearch_to_tsquery(?::regconfig, ?)) AND locale = ? )) UNION (SELECT product_id FROM products_nutrition_facts WHERE id IN (SELECT product_nutrition_fact_id FROM products_nutrition_facts_names WHERE nutrient_name_id IN (SELECT id FROM nutrients_names WHERE (value ILIKE ? OR ts_value @@ websearch_to_tsquery(?::regconfig, ?)) AND locale = ? ))) )) 
middleware_1  | 2023-03-13T16:55:50.430Z <> {thread=http-nio-8080-exec-2} DEBUG: [com.test.mw.db.mappers.SearchMapper.getSearchProductsCount] com.test.mw.db.mappers.SearchMapper.getSearchProductsCountrlf(==> Parameters: 45.53563(Double), 45.4457(Double), -73.40128(Double), -73.52957(Double), en(String), %tt%(String), %tt%(String), %tt%(String), %tt%(String), %tt%(String), english(String), tt(String), english(String), tt(String), en(String), %tt%(String), english(String), tt(String), en(String), %tt%(String), english(String), tt(String), en(String), %tt%(String), english(String), tt(String), en(String), %tt%(String), english(String), tt(String), en(String), %tt%(String), english(String), tt(String), en(String))

The transaction status on postgresql side looks like this:

16384   mw  68  39  10  user    PostgreSQL JDBC Driver              2023-03-13 12:55:50.684 -0400       2023-03-13 12:55:50.470 -0400   2023-03-13 12:55:50.701 -0400           active              "SELECT count(*)
        FROM products p
        LEFT JOIN products_locations pl ON pl.product_id = p.id  AND (pl.latitude <= $1 OR pl.latitude IS NULL)  
          AND (pl.latitude >= $2 OR pl.latitude IS NULL) 
          AND (pl.longitude <= $3 OR pl.longitude IS NULL)  
          AND (pl.longitude >= $4 OR pl.longitude IS NULL) 
        LEFT JOIN products_descriptions pd ON pd.product_id = p.id  AND pd.locale = $5 
        WHERE 1 = 1
                AND p.id IN (
                    (SELECT id FROM products WHERE universal_product_code ILIKE $6 OR model ILIKE $7 OR isbn ILIKE $8) UNION
                    (SELECT product_id FROM products_descriptions WHERE (title ILIKE $9 OR description ILIKE $10 OR ts_title @@ websearch_to_tsquery($11::regconfig, $12) OR ts_description @@ websearch_to_tsquery($13::regconfig, $14))  AND locale = $15 ) UNION
                    (SELECT product_id FROM products_conte" parallel worker

My postgresql docker definition looks like this:

FROM groonga/pgroonga:latest-alpine-15-slim

# install wget curl iconv
RUN apk add --no-cache wget curl

# install polish full text search
RUN wget https://sjp.pl/sl/ort/sjp-ispell-pl-20230301-src.tar.bz2
RUN tar xvjf sjp-ispell-pl-20230301-src.tar.bz2
RUN cd sjp-ispell-pl-20230301 \
    iconv -f ISO_8859-2 -t utf-8 polish.aff > polish.affix \
    iconv -f ISO_8859-2 -t utf-8 polish.all > polish.dict
RUN curl https://raw.githubusercontent.com/dominem/stopwords/master/polish.stopwords.txt > polish.stop
RUN cp polish.affix `pg_config --sharedir`/tsearch_data/
RUN cp polish.dict `pg_config --sharedir`/tsearch_data/
RUN cp polish.stop `pg_config --sharedir`/tsearch_data/

I just added polish full text support on top of pgroonga container.

I have about 25k unique products entries in my products DB

Any idea what might be causing mybatis to hang on these request ?

Thanks

ghevge commented 1 year ago

BTW I was seeing the same behavior with some older versions too:

2.7.3 5.0.1 42.4.0 3.5.11 2.0.7 2.2.2
ghevge commented 1 year ago

My spring DS config looks like this:

spring:
  application:
    name: test
  datasource:
    jdbc-url: jdbc:postgresql://mw-db:5432/mw
    username: *****
    password: *****
    idle-timeout: 60000
    minimum-idle: 20
    connection-timeout: 60000
    pool-name: AppPool
    initialization-fail-timeout: 30000
    login-timeout: 30000
ghevge commented 1 year ago

The parametrized query looks like this:

SELECT count(*) 
FROM products p 
LEFT JOIN products_locations pl ON pl.product_id = p.id AND (pl.latitude <= 45.53563 OR pl.latitude IS NULL) AND (pl.latitude >= 45.4457 OR pl.latitude IS NULL) AND (pl.longitude <= -73.40128 OR pl.longitude IS NULL) AND (pl.longitude >= -73.52957 OR pl.longitude IS NULL) 
LEFT JOIN products_descriptions pd ON pd.product_id = p.id AND pd.locale = 'en' 
WHERE 1 = 1 AND p.id IN ( 
(SELECT id FROM products WHERE universal_product_code ILIKE '%tt%' OR model ILIKE '%tt%' OR isbn ILIKE '%tt%') 
UNION 
(SELECT product_id FROM products_descriptions WHERE (title ILIKE '%tt%' OR description ILIKE '%tt%' OR ts_title @@ websearch_to_tsquery('english'::regconfig, '%tt%') OR ts_description @@ websearch_to_tsquery('english'::regconfig, '%tt%')) AND locale = 'en' ) 
UNION 
(SELECT product_id FROM products_contents WHERE content_id IN (SELECT id FROM contents WHERE (value ILIKE '%tt%' OR ts_value @@ websearch_to_tsquery('english'::regconfig, '%tt%')) AND locale = 'en' ))
 UNION 
 (SELECT product_id FROM products_tags WHERE tag_id IN (SELECT id FROM tags WHERE (value ILIKE '%tt%' OR ts_value @@ websearch_to_tsquery('english'::regconfig, '%tt%')) AND locale = 'en' ))
 UNION (SELECT product_id FROM products_labels WHERE label_id IN (SELECT id FROM labels WHERE (value ILIKE '%tt%' OR ts_value @@ websearch_to_tsquery('english'::regconfig, '%tt%')) AND locale = 'en' ))
 UNION (SELECT product_id FROM products_brands WHERE brand_id IN (SELECT id FROM brands WHERE (value ILIKE '%tt%' OR ts_value @@ websearch_to_tsquery('english'::regconfig, '%tt%')) AND locale = 'en' )) 
 UNION (SELECT product_id FROM products_nutrition_facts WHERE id IN (SELECT product_nutrition_fact_id FROM products_nutrition_facts_names WHERE nutrient_name_id IN (SELECT id FROM nutrients_names WHERE (value ILIKE '%tt%' OR ts_value @@ websearch_to_tsquery('english'::regconfig, '%tt%')) AND locale = 'en' ))) )