Spring boot starter parent 3.0.6
I have a controller that accepts get params and pageable for searching cards for trading card game:
@RestController
@RequestMapping("/api/cards")
@RequiredArgsConstructor
public class CardsController {
private final BerserkHeroesCardService cardService;
@GetMapping
@ResponseBody
public Page<BerserkCardModel> getCards(CardSearchRequest searchRequest, Pageable pageable) {
return cardService.getCards(searchRequest, pageable);
}
}
calling http://.../api/cards?page=1&size=12 I get correct result:
...
"last": false,
"totalPages": 228,
"totalElements": 2726,
"size": 12,
...
calling http://.../api/cards?page=2&size=12 I got not expected and incorrect result
...
"last": true,
"totalPages": 2,
"totalElements": 23,
"size": 12,
...
calling http://.../api/cards?page=3&size=12 I got also incorrect result that differ previous
...
"last": true,
"totalPages": 3,
"totalElements": 35,
"size": 12,
...
calling http://.../api/cards?page=4&size=12 again return correct result
...
"last": false,
"totalPages": 228,
"totalElements": 2726,
"size": 12,
...
My serviece method
@Override
public Page<BerserkCardModel> getCards(CardSearchRequest request, Pageable pageable) {
Specification<BerserkCard> spec = Specification.where(null); // mocked for debug
Page<BerserkCard> all = berserkCardRepo.findAll(spec, pageable); // findAll returned page incorrect
//result for page 2 and 3
return all.map(mapper::toModel);
}
I'im trying to find info about similar bugs but nothing found. Other same services works well.
UPD
I experimented with my jpa repository and commented @EntityGraph annotation
and page request now return correct result regardless of page number.
public interface BerserkCardRepo extends JpaRepository<BerserkCard, Long>, JpaSpecificationExecutor<BerserkCard> {
@Override
//@EntityGraph(attributePaths = {"elements"})
Page<BerserkCard> findAll(@Nullable Specification<BerserkCard> spec, Pageable pageable);
}
UPD2
also I'm noticed that for 2 and 3 pages hibernate didn't generate count query. For each other page hibernate does it.
UPD3
I added logging sql when entity graph enabled.
service:
@Override
public Page<BerserkCardModel> getCards(CardSearchRequest request, Pageable pageable) {
log.info(String.format("Accept pageable. Page %d, size %d", pageable.getPageNumber(), pageable.getPageSize()));
Specification<BerserkCard> spec = Specification.where(null);
Page<BerserkCard> all = berserkCardRepo
.findAll(spec, pageable);
log.info(String.format("Found %d elements, total pages: %d", all.getTotalElements(), all.getTotalPages()));
return all
.map(mapper::toModel);
}
Repo:
public interface BerserkCardRepo extends JpaRepository<BerserkCard, Long>, JpaSpecificationExecutor<BerserkCard> {
@Override
@EntityGraph(attributePaths = {"elements"})
Page<BerserkCard> findAll(@Nullable Specification<BerserkCard> spec, Pageable pageable);
}
Entity:
@Data
@Entity
@Table(name = "berserk_cards")
public class BerserkCard {
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
private Long id;
private String set;
private String name;
private Integer cost;
@ElementCollection
@CollectionTable(name = "berserk_card_elements", joinColumns = @JoinColumn(name = "card_id"))
@Column(name = "element")
private Set<String> elements = new HashSet<>();
private String type;
private String subtype;
private Integer attack;
private Integer health;
private String rarity;
private String text;
private String painter;
private Integer number;
}
It's ok, that page in url start has value = 1, and in logs = 0 because i have configured one-indexed-parameters: true.
Calling http://.../api/cards?page=1&size=12
2023-05-15T10:06:51.411+03:00 INFO 21056 --- [nio-9999-exec-1] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 0, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
e1_0.card_id,
e1_0.element,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0
left join
berserk_card_elements e1_0
on b1_0.id=e1_0.card_id offset ? rows fetch first ? rows only
Hibernate:
select
count(b1_0.id)
from
berserk_cards b1_0
2023-05-15T10:06:51.472+03:00 INFO 21056 --- [nio-9999-exec-1] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 2726 elements, total pages: 228
Calling http://.../api/cards?page=2&size=12
2023-05-15T10:06:53.277+03:00 INFO 21056 --- [nio-9999-exec-5] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 1, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
e1_0.card_id,
e1_0.element,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0
left join
berserk_card_elements e1_0
on b1_0.id=e1_0.card_id offset ? rows fetch first ? rows only
2023-05-15T10:06:53.300+03:00 INFO 21056 --- [nio-9999-exec-5] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 23 elements, total pages: 2
Calling http://.../api/cards?page=3&size=12
2023-05-15T10:06:54.272+03:00 INFO 21056 --- [nio-9999-exec-2] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 2, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
e1_0.card_id,
e1_0.element,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0
left join
berserk_card_elements e1_0
on b1_0.id=e1_0.card_id offset ? rows fetch first ? rows only
2023-05-15T10:06:54.299+03:00 INFO 21056 --- [nio-9999-exec-2] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 35 elements, total pages: 3
Calling http://.../api/cards?page=4&size=12
2023-05-15T10:06:55.521+03:00 INFO 21056 --- [nio-9999-exec-9] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 3, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
e1_0.card_id,
e1_0.element,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0
left join
berserk_card_elements e1_0
on b1_0.id=e1_0.card_id offset ? rows fetch first ? rows only
Hibernate:
select
count(b1_0.id)
from
berserk_cards b1_0
2023-05-15T10:06:55.561+03:00 INFO 21056 --- [nio-9999-exec-9] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 2726 elements, total pages: 228
and now i commented entity graph annotation
public interface BerserkCardRepo extends JpaRepository<BerserkCard, Long>, JpaSpecificationExecutor<BerserkCard> {
@Override
//@EntityGraph(attributePaths = {"elements"})
Page<BerserkCard> findAll(@Nullable Specification<BerserkCard> spec, Pageable pageable);
}
Calling http://.../api/cards?page=1&size=12
2023-05-15T10:14:26.704+03:00 INFO 4036 --- [nio-9999-exec-4] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 0, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0 offset ? rows fetch first ? rows only
Hibernate:
select
count(b1_0.id)
from
berserk_cards b1_0
2023-05-15T10:14:26.742+03:00 INFO 4036 --- [nio-9999-exec-4] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 2726 elements, total pages: 228
Calling http://.../api/cards?page=2&size=12
2023-05-15T10:15:47.211+03:00 INFO 4036 --- [nio-9999-exec-3] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 1, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0 offset ? rows fetch first ? rows only
Hibernate:
select
count(b1_0.id)
from
berserk_cards b1_0
2023-05-15T10:15:47.250+03:00 INFO 4036 --- [nio-9999-exec-3] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 2726 elements, total pages: 228
Calling http://.../api/cards?page=3&size=12(the same for all other pages)
2023-05-15T10:17:03.992+03:00 INFO 4036 --- [io-9999-exec-10] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Accept pageable. Page 2, size 12
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0 offset ? rows fetch first ? rows only
Hibernate:
select
count(b1_0.id)
from
berserk_cards b1_0
2023-05-15T10:17:04.029+03:00 INFO 4036 --- [io-9999-exec-10] r.b.c.i.h.s.BerserkHeroesCardServiceImpl : Found 2726 elements, total pages: 228
As You can see, the differ in logs between wrong response and correct response is count query, which is not generated in incorrect response case.
Any have idea why is this happening?
Problem in eager collection elements.
If we see at sql in logs
Hibernate:
select
b1_0.id,
b1_0.attack,
b1_0.cost,
e1_0.card_id,
e1_0.element,
b1_0.health,
b1_0.name,
b1_0.number,
b1_0.painter,
b1_0.rarity,
b1_0.set,
b1_0.subtype,
b1_0.text,
b1_0.type
from
berserk_cards b1_0
left join
berserk_card_elements e1_0
on b1_0.id=e1_0.card_id offset ? rows fetch first ? rows only
We found that we skip ? rows and fetch ? rows. If there are two or more elements card has, we will found less unique entities in result set.
For example, in resultSet we have one card with two elements, and other with 1 elements. It means in resultSet we have 11 unique entities.
When spring parse resultSet to entities it found, that there are 11 entities it found meanwhile page size is 12. Spring saw that founded count of entities less than page size and it thinks that it's last page and don't call count query.