[MySQL] Insert query met NOW() geeft vreemde resultaten

[Pelle]

Hi /14,

Ik heb een heel raar probleem met MySQL. Aanschouw dit snippet code:

PHP:

Database::query(sprintf("
    INSERT INTO
        productpricehistory (
            product_id, 
            price_old, 
            price_new, 
            date_pricechange
        ) VALUES (
            %d,
            %f,
            %f,
            NOW()
        )",
    $product_id,
    $price,
    $price_new
));

De tabel-structuur is deze:

SQL:

CREATE TABLE `productpricehistory` (
  `productpricehistory_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `product_id` int(10) unsigned NOT NULL,
  `price_old` decimal(10,2) DEFAULT NULL,
  `price_new` decimal(10,2) DEFAULT NULL,
  `date_pricechange` datetime DEFAULT NULL
  PRIMARY KEY (`productpricehistory_id`),
  KEY `ix_product` (`product_id`)
) ENGINE=MyISAM DEFAULT CHARSET=latin1 COLLATE=latin1_general_ci;

Als ik nu echter de tabel bekijk dan zie ik het productpricehistory_id netjes oplopen, maar de date_pricechange vertoont soms hele gekke schommelingen. Voorbeeldje:

code:

productpricehistory_id product_id price_old price_new date_pricechange
8512                   6923       399       479       2014-10-26 23:09:56 
8513                   6924       399       479       2014-10-26 23:10:03 
8514                   5198       376       349       2014-10-27 12:00:04 
8515                   7596       28        27        2014-06-15 23:00:04 
8516                   7596       29        28        2014-05-31 17:00:04 
8517                   7596       27        29        2014-05-27 00:25:11 
8518                   7596       28        27        2014-04-13 12:00:03 
8519                   7596       27        29        2014-10-27 13:06:44 
8520                   4285       289       285       2014-10-27 23:00:04 
8521                   1484       193       185       2014-10-27 23:00:04

Als je een auto-increment PK hebt, en bij ieder nieuw record date_pricechange op NOW() zet, dan zou het toch helemaal niet moeten kunnen dat de datum bij oplopende PK opeens dipt van 27 oktober naar 15 juni (naar 31 mei, naar 27 mei, naar 13 april) en vervolgens weer netjes terug schiet?

Ik ben er verder in gaan duiken, en als ik de prijs-veranderingen van 1 product op PK gesorteerd bekijk, dan zou het altijd zo moeten zijn dat price_new van een record altijd price_old van het opeenvolgende record moet zijn. Maar dat is niet zo, kijk maar:

code:

productpricehistory_id product_id price_old price_new date_pricechange
8458                   7595       283       299       2014-10-22 10:05:14 
8459                   7595       299       283       2014-10-12 08:00:04 
8460                   7595       285       299       2014-09-30 20:24:55

Het gaat mis van 8459 naar 8460: de prijs van 283 gaat opeens naar 285. Sorteer je echter op date_pricechange (ASC) dan klopt de volgorde wel. Het laatste blijkt voor alle producten te kloppen; deze tabel gesorteerd op date_pricechange geeft altijd logisch resultaten, maar gesorteerd op productpricehistory_id niet. Hoe kan dat Het is vast iets simpels, maar ik zie het niet

[Verwijderd]

Ik ben geneigd te zeggen dat dit ofwel een leuke bug is, of dat er iets vreselijk mis is met het platform waar dit op draait.
Kun je iets vertellen over gebruikte versies van het OS en de DBMS? Is het echt MySQL of is het soms MariaDB of Percona?

Draait dit in een virtuele server of op bare metal? Zie je in andere logs ook fluctuaties, zoals in system logs en dergelijke? Ik neem aan dat de tijd wordt gesynchroniseerd met NTP, of als het een virtuele server is wordt de tijd wellicht via een agent gelijkgesteld aan de systeemtijd van het platform.

Ik heb dergelijke rare sprongen wel gezien met bijvoorbeeld live migraties van virtuele servers van een VMware host naar een andere waarbij de systeemtijd van de hosts niet klopte.

Overigens zou ik nooit meer MyISAM gebruiken maar altijd InnoDB vanwege ondersteuning van transacties en referentiele integriteit. En natuurlijk UTF-8 by default. Maar dat alles is natuurlijk helemaal offtopic.

[Gomez12]

Verwijder je wel eens records uit die tabel?

Want in principoe is een auto_increment niet altijd 100% oplopend. Hij heeft in wezen een begintellertje met de laatste waarde en hij gaat het eerstvolgende vrije getalletje daarboven pakken.

Heb je nou ooit de records verwijdert 8512, 8513, 8514 verwijdert dan waren die dus vrij terwijl 8515 "bezet" was. In principe geen enkel probleem (want het tellertje staat hoger), totdat je dus ergens met een handeling het tellertje gereset hebt, dan begint hij in wezen opnieuw te nummeren vanaf 1 (of net waar het tellertje op stond) en zoeken naar het eerste vrije nummer. En dan komt hij dus opeens 8512, 8513, 8514 tegen en die zijn vrij en mogen gebruikt worden.

P.s. ik zou je afraden om in id's logica te willen stoppen (zoals volgorde oid) wil je logica dan moet je of extra velden aanmaken of je moet je pk zetten over logische velden en geen id aanmaken.
Een auto_increment heeft allemaal voorzieningen in zich (zoals resetten tellertje, maar ook wat te doen bij een overflow) die op de korte termijn niet zichtbaar zijn, maar op de lange termijn je logica omver schoppen.

[Morax]

Even een paar basic dingen, want je opzet lijkt op zich goed:

- Je werkt met maar 1 MySQL server, of werk je met een cluster? (waarbij de tijd van 1 van de servers mogelijk niet goed staat)
- De code voor het inserten voor een record, je bent er 100% zeker van dat dat de enige plek is in je systeem waar een insert in deze tabel wordt gedaan?

[Pelle]

Verwijderd schreef op donderdag 30 oktober 2014 @ 01:33:
Ik ben geneigd te zeggen dat dit ofwel een leuke bug is, of dat er iets vreselijk mis is met het platform waar dit op draait.
Kun je iets vertellen over gebruikte versies van het OS en de DBMS? Is het echt MySQL of is het soms MariaDB of Percona?

Draait dit in een virtuele server of op bare metal?

MySQL 5.0 op Linux Debian. Het is een VPS overigens, dus geen fysieke server.

Zie je in andere logs ook fluctuaties, zoals in system logs en dergelijke? Ik neem aan dat de tijd wordt gesynchroniseerd met NTP, of als het een virtuele server is wordt de tijd wellicht via een agent gelijkgesteld aan de systeemtijd van het platform.

Systeemtijd staat gewoon goed. Ik heb nog geen andere logs bekeken, maar ik zou ook even de bestellingen-tabel na kunnen lopen. Kom ik nog op terug.

Overigens zou ik nooit meer MyISAM gebruiken maar altijd InnoDB vanwege ondersteuning van transacties en referentiele integriteit. En natuurlijk UTF-8 by default. Maar dat alles is natuurlijk helemaal offtopic.

Ik zou dat normaal gesproken ook niet meer doen inderdaad, maar in dit geval is deze tabel consistent gehouden met de rest van de database-tabellen.

Gomez12 schreef op donderdag 30 oktober 2014 @ 08:56:
Verwijder je wel eens records uit die tabel?

Nope.

Want in principoe is een auto_increment niet altijd 100% oplopend. Hij heeft in wezen een begintellertje met de laatste waarde en hij gaat het eerstvolgende vrije getalletje daarboven pakken.

Heb je nou ooit de records verwijdert 8512, 8513, 8514 verwijdert dan waren die dus vrij terwijl 8515 "bezet" was. In principe geen enkel probleem (want het tellertje staat hoger), totdat je dus ergens met een handeling het tellertje gereset hebt, dan begint hij in wezen opnieuw te nummeren vanaf 1 (of net waar het tellertje op stond) en zoeken naar het eerste vrije nummer. En dan komt hij dus opeens 8512, 8513, 8514 tegen en die zijn vrij en mogen gebruikt worden.

Het was het eerste wat ik heb gechecked; of er toevallig ook code is die records verwijdert. Maar dat is er niet (sterker nog, dan had ik het moeten weten, omdat ik dat dan zelf geschreven zou moeten hebben ).

P.s. ik zou je afraden om in id's logica te willen stoppen (zoals volgorde oid) wil je logica dan moet je of extra velden aanmaken of je moet je pk zetten over logische velden en geen id aanmaken.
Een auto_increment heeft allemaal voorzieningen in zich (zoals resetten tellertje, maar ook wat te doen bij een overflow) die op de korte termijn niet zichtbaar zijn, maar op de lange termijn je logica omver schoppen.

Klopt, er zit ook geen logica of afhankelijkheid in gelukkig. Het probleem is gewoon dat ik niet snap hoe het kan. Ik wil alleen uitsluiten dat dit ooit voor andere functionaliteiten op hetzelfde platform een probleem oplevert, vandaar dat ik me er even in aan het vastbijten ben

Morax schreef op donderdag 30 oktober 2014 @ 10:02:
Even een paar basic dingen, want je opzet lijkt op zich goed:

- Je werkt met maar 1 MySQL server, of werk je met een cluster? (waarbij de tijd van 1 van de servers mogelijk niet goed staat)

1 MySQL server ja, die alleen vanaf localhost te benaderen is.

- De code voor het inserten voor een record, je bent er 100% zeker van dat dat de enige plek is in je systeem waar een insert in deze tabel wordt gedaan?

Yep.

[P.O. Box]

nvm, had je laatste regel niet gelezen

[ Voor 82% gewijzigd door P.O. Box op 30-10-2014 16:24 ]

[Voutloos]

^ Dat. En dan krijg je deze staat als je een keertje export+import of insert into...select hebt gedaan zonder de nu aangenomen volgorde of zonder bestaande id's gespecificeerd.

edit:
Fijn zo'n edit, maar ik zet gewoon in op dat P.O. Box gelijk heeft. Alle kolommmen beh. id zijn juist en je hebt het id gewoon een keertje verprutst.

[ Voor 31% gewijzigd door Voutloos op 30-10-2014 16:30 ]

[Pelle]

Het is niet slechts 1 keer voorgekomen, het is over een periode van een paar maanden vaker voorgekomen. Dat maakt het nog eens extra vreemd (maar daardoor waarschijnlijk ook minder incident-afhankelijk en wellicht beter te traceren).

[Joolee]

Ik denk dat de host waarop je VM draait de tijd verkeerd heeft staan. Je client tools zijn ingesteld om de tijd te synchroniseren en je server synchroniseerd ook met een ntp server. Dat zorgt ervoor dat de tijd soms goed staat (na ntp sync) en soms verkeerd (na vm host sync)
Het kan ook zijn dat dit probleem niet in je VM zit maar in de NTP server van je VM of host.

[Voutloos]

Nee, in de ts staat dat gesorteerd op tijdstip gewoon logische resultaten geeft. Met random tijden vanuit je os/ntp whatever zou dat wel heel erg sterk zijn.

Weet eigenlijk gewoon zeker dat ik de oorzaak al noemde (batch inserts zonder id of goede volgorde).

[ Voor 8% gewijzigd door Voutloos op 30-10-2014 21:43 ]

[P.O. Box]

excuus voor de edit ... ik zet ook in op een batch insert of back-up/mysqldump terugzetten

[ Voor 5% gewijzigd door P.O. Box op 31-10-2014 00:09 ]

[Gomez12]

P.O. Box schreef op donderdag 30 oktober 2014 @ 23:40:
excuus voor de edit ... ik zet ook in op een batch insert of back-up/mysqldump terugzetten

Ik ga er toch vanuit dat een back-up / mysqldump gewoon de goede id's bevat en ook de counter goedzet (anders is MYSQL nog crappier als ik al dacht)

Dus dan houdt je bijna alleen nog maar een batch insert / database mutatie over.

[ValHallASW]

Wat me opvalt: de entries waarin de datum verspringt zijn allemaal van hetzelfde product:

code:

productpricehistory_id product_id price_old price_new date_pricechange
8515                   7596       28        27        2014-06-15 23:00:04 
8516                   7596       29        28        2014-05-31 17:00:04 
8517                   7596       27        29        2014-05-27 00:25:11 
8518                   7596       28        27        2014-04-13 12:00:03 
8519                   7596       27        29        2014-10-27 13:06:44

Heb je nog relaties tussen tabellen, met bijvoorbeeld een ON UPDATE CASCADE oid? Of heb je stiekem toch nog een stuk code dat voor nieuwe producten historische informatie inleest?

[ Voor 12% gewijzigd door ValHallASW op 31-10-2014 08:55 ]